[Users] latest vdsm cannot read ib device speeds causing storage attach fail

Shu Ming shuming at linux.vnet.ibm.com
Thu Jan 31 02:27:10 UTC 2013


Royce,

It is a good trouble shooting.  See my comments about the IOError in 
serve_client() below.

Royce Lv:
>
> Hi,
>    I reproduced this issue, and I believe it's a python bug.
>    1. How to reproduce:
>    with the test case attached, put it under /usr/share/vdsm/tests/, 
> run #./run_tests.sh superVdsmTests.py
>    and this issue will be reproduced.
>    2.Log analyse:
>    We notice a strange pattern in this log: connectStorageServer be 
> called twice, first supervdsm call succeed, second fails becasue of  
> validateAccess().
>    That is because for the first call validateAccess returns normally 
> and leave a child there, when the second validateAccess call arrives 
> and multirprocessing manager is receiving the method message, it is 
> just the time first child exit and SIGCHLD comming, this signal 
> interrupted multiprocessing receive system call, python managers.py 
> should handle INTR and retry recv() like we do in vdsm but it's not, 
> so the second one raise error.
> >Thread-18::DEBUG::2013-01-22 10:41:03,570::misc::85::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6,nfsvers=3 192.168.0.1:/ovirt/silvermoon /rhev/data-center/mnt/192.168.0.1:_ovirt_silvermoon' (cwd None)
> >Thread-18::DEBUG::2013-01-22 10:41:03,607::misc::85::Storage.Misc.excCmd::(<lambda>) '/usr/bin/sudo -n /bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6,nfsvers=3 192.168.0.1:/ovirt/undercity /rhev/data-center/mnt/192.168.0.1:_ovirt_undercity' (cwd None)
> >Thread-18::ERROR::2013-01-22 10:41:03,627::hsm::2215::Storage.HSM::(connectStorageServer) Could not connect to storageServer
> >Traceback (most recent call last):
> >  File "/usr/share/vdsm/storage/hsm.py", line 2211, in connectStorageServer
> >    conObj.connect()
> >  File "/usr/share/vdsm/storage/storageServer.py", line 303, in connect
> >    return self._mountCon.connect()
> >  File "/usr/share/vdsm/storage/storageServer.py", line 209, in connect
> >    fileSD.validateDirAccess(self.getMountObj().getRecord().fs_file)
> >  File "/usr/share/vdsm/storage/fileSD.py", line 55, in validateDirAccess
> >    (os.R_OK | os.X_OK))
> >  File "/usr/share/vdsm/supervdsm.py", line 81, in __call__
> >    return callMethod()
> >  File "/usr/share/vdsm/supervdsm.py", line 72, in <lambda>
> >    **kwargs)
> >  File "<string>", line 2, in validateAccess
> >  File "/usr/lib64/python2.6/multiprocessing/managers.py", line 740, in _callmethod
> >    raise convert_to_error(kind, result)
> the vdsm side receive RemoteError because of supervdsm server 
> multiprocessing manager raise error KIND='TRACEBACK'
>   >RemoteError:
> The upper part is the trace back from the client side, the following 
> part is from server side:
> >---------------------------------------------------------------------------
> >Traceback (most recent call last):
> >  File "/usr/lib64/python2.6/multiprocessing/managers.py", line 214, in serve_client
> >    request = recv()
> >IOError: [Errno 4] Interrupted system call
> >---------------------------------------------------------------------------
>
> Corresponding Python source code:managers.py(Server side)
>      def serve_client(self, conn):
>          '''
>          Handle requests from the proxies in a particular process/thread
>          '''
>          util.debug('starting server thread to service %r',
>                     threading.current_thread().name)
>          recv = conn.recv
>          send = conn.send
>          id_to_obj = self.id_to_obj
>          while not self.stop:
>              try:
>                  methodname = obj = None
>                  request = recv()<------------------this line been interrupted by SIGCHLD
>                  ident, methodname, args, kwds = request
>                  obj, exposed, gettypeid = id_to_obj[ident]
>                  if methodname not in exposed:
>                      raise AttributeError(
>                          'method %r of %r object is not in exposed=%r' %
>                          (methodname, type(obj), exposed)
>                          )
>                  function = getattr(obj, methodname)
>                  try:
>                      res = function(*args, **kwds)
>                  except Exception, e:
>                      msg = ('#ERROR', e)
>                  else:
>                      typeid = gettypeid and gettypeid.get(methodname, None)
>                      if typeid:
>                          rident, rexposed = self.create(conn, typeid, res)
>                          token = Token(typeid, self.address, rident)
>                          msg = ('#PROXY', (rexposed, token))
>                      else:
>                          msg = ('#RETURN', res)
>              except AttributeError:
>                  if methodname is None:
>                      msg = ('#TRACEBACK', format_exc())
>                  else:
>                      try:
>                          fallback_func = self.fallback_mapping[methodname]
>                          result = fallback_func(
>                              self, conn, ident, obj, *args, **kwds
>                              )
>                          msg = ('#RETURN', result)
>                      except Exception:
>                          msg = ('#TRACEBACK', format_exc())
>
>              except EOFError:
>                  util.debug('got EOF -- exiting thread serving %r',
>                             threading.current_thread().name)
>                  sys.exit(0)
>
>              except Exception:<------does not handle IOError,INTR here should retry recv()
>                  msg = ('#TRACEBACK', format_exc())
Not sure I under what is your opinion here.

Whenever this line was interrupted by a SIGCHLD ,

request = recv()<------------------this line been interrupted by SIGCHLD

the code flow should fall into

  except Exception:<------does not handle IOError,INTR here should retry recv()
                 msg = ('#TRACEBACK', format_exc())


However, the big while loop was not stopped, it should reach this line again.

try:

                 methodname = obj = None

                 request = recv()<------------------this line been interrupted by SIGCHLD

Then the interrupted recv() will be called again and again until the 
recv() call is not interrupted.   What's wrong here?

>
>
> 3. Actions we will take:
> (1)As a work round we can first remove the zombie reaper from 
> supervdsm server
> (2)I'll see whether python has a fixed version for this
> (3)Yaniv is working on changing vdsm/svdsm communication channel to 
> pipe and handle it ourselves, I believe we'll get rid of this with 
> that properly handled.
>
>
> On 01/25/2013 06:00 AM, Dead Horse wrote:
>> Tried some manual edits to SD states in the dbase. The net result was 
>> I was able to get a node active. However as reconstructing the master 
>> storage domain kicked in it was unable to do so. It was also not able 
>> to recognize the other SD with similar failure modes to the 
>> unrecognized master above. Guessing the newer VDSM version borked 
>> things pretty good. So being as this is a test harness and the SD 
>> data is not worth saving I just smoked the all SD. I ran 
>> engine-cleanup and started from fresh and all is well now.
>>
>> - DHC
>>
>>
>> On Thu, Jan 24, 2013 at 11:53 AM, Dead Horse 
>> <deadhorseconsulting at gmail.com 
>> <mailto:deadhorseconsulting at gmail.com>> wrote:
>>
>>     This test harness setup here consists of two servers tied to NFS
>>     storage via IB (NFS mounts are via IPoIB, NFS over RDMA is
>>     disabled) . All storage domains are NFS. The issue does occur
>>     with both servers on when attempting to bring them out of
>>     maintenance mode with the end result being non-operational due to
>>     storage attach fail.
>>
>>     The current issue is now that with a working older commit the
>>     master storage domain is "stuck" in state "locked" and I see the
>>     secondary issue wherein VDSM cannot seem to find or contact the
>>     master storage domain even though it is there. I am can mount the
>>     master storage domain manually and and all content appears to be
>>     accounted for accordingly on either host.
>>
>>     Here is the current contents of the master storage domain metadata:
>>     CLASS=Data
>>     DESCRIPTION=orgrimmar
>>     IOOPTIMEOUTSEC=1
>>     LEASERETRIES=3
>>     LEASETIMESEC=5
>>     LOCKPOLICY=
>>     LOCKRENEWALINTERVALSEC=5
>>     MASTER_VERSION=417
>>     POOL_DESCRIPTION=Azeroth
>>     POOL_DOMAINS=0549ee91-4498-4130-8c23-4c173b5c0959:Active,d8b55105-c90a-465d-9803-8130da9a671e:Active,67534cca-1327-462a-b455-a04464084b31:Active,c331a800-839d-4d23-9059-870a7471240a:Active,f8984825-ff8d-43d9-91db-0d0959f8bae9:Active,c434056e-96be-4702-8beb-82a408a5c8cb:Active,f7da73c7-b5fe-48b6-93a0-0c773018c94f:Active,82e3b34a-6f89-4299-8cd8-2cc8f973a3b4:Active,e615c975-6b00-469f-8fb6-ff58ae3fdb2c:Active,5bc86532-55f7-4a91-a52c-fad261f322d5:Active,1130b87a-3b34-45d6-8016-d435825c68ef:Active
>>     POOL_SPM_ID=1
>>     POOL_SPM_LVER=6
>>     POOL_UUID=f90a0d1c-06ca-11e2-a05b-00151712f280
>>     REMOTE_PATH=192.168.0.1:/ovirt/orgrimmar
>>     ROLE=Master
>>     SDUUID=67534cca-1327-462a-b455-a04464084b31
>>     TYPE=NFS
>>     VERSION=3
>>     _SHA_CKSUM=1442bb078fd8c9468d241ff141e9bf53839f0721
>>
>>     So now with the older working commit I now get this the
>>     "StoragePoolMasterNotFound: Cannot find master domain" error
>>     (prior details above when I worked backwards to that commit)
>>
>>     This is odd as the nodes can definitely reach the master storage
>>     domain:
>>
>>     showmount from one of the el6.3 nodes:
>>     [root at kezan ~]# showmount -e 192.168.0.1
>>     Export list for 192.168.0.1 <http://192.168.0.1>:
>>     /ovirt/orgrimmar 192.168.0.0/16 <http://192.168.0.0/16>
>>
>>     mount/ls from one of the nodes:
>>     [root at kezan ~]# mount 192.168.0.1:/ovirt/orgrimmar /mnt
>>     [root at kezan ~]# ls -al
>>     /mnt/67534cca-1327-462a-b455-a04464084b31/dom_md/
>>     total 1100
>>     drwxr-xr-x 2 vdsm kvm    4096 Jan 24 11:44 .
>>     drwxr-xr-x 5 vdsm kvm    4096 Oct 19 16:16 ..
>>     -rw-rw---- 1 vdsm kvm 1048576 Jan 19 22:09 ids
>>     -rw-rw---- 1 vdsm kvm       0 Sep 25 00:46 inbox
>>     -rw-rw---- 1 vdsm kvm 2097152 Jan 10 13:33 leases
>>     -rw-r--r-- 1 vdsm kvm     903 Jan 10 13:39 metadata
>>     -rw-rw---- 1 vdsm kvm       0 Sep 25 00:46 outbox
>>
>>
>>     - DHC
>>
>>
>>
>>     On Thu, Jan 24, 2013 at 7:51 AM, ybronhei <ybronhei at redhat.com
>>     <mailto:ybronhei at redhat.com>> wrote:
>>
>>         On 01/24/2013 12:44 AM, Dead Horse wrote:
>>
>>             I narrowed down on the commit where the originally
>>             reported issue crept in:
>>             commitfc3a44f71d2ef202cff18d7203b9e4165b546621building
>>             and testing with
>>
>>             this commit or subsequent commits yields the original issue.
>>
>>         Interesting.. it might be related to this commit and we're
>>         trying to reproduce it.
>>
>>         Did you try to remove that code and run again? does it work
>>         without the additional of zombieReaper?
>>         does the connectivity to the storage work well? when you run
>>         'ls' on the mounted folder you get see the files without a
>>         long delay ? it might related to too long timeout when
>>         validating access to this mount..
>>         we work on that.. any additional info can help
>>
>>         Thanks.
>>
>>
>>             - DHC
>>
>>
>>             On Wed, Jan 23, 2013 at 3:56 PM, Dead Horse
>>             <deadhorseconsulting at gmail.com
>>             <mailto:deadhorseconsulting at gmail.com>>wrote:
>>
>>                 Indeed reverting back to an older vdsm clears up the
>>                 above issue. However
>>                 now I the issue is see is:
>>                 Thread-18::ERROR::2013-01-23
>>                 15:50:42,885::task::833::TaskManager.Task::(_setError)
>>                 Task=`08709e68-bcbc-40d8-843a-d69d4df40ac6`::Unexpected
>>                 error
>>
>>                 Traceback (most recent call last):
>>                    File "/usr/share/vdsm/storage/task.py", line 840,
>>                 in _run
>>                      return fn(*args, **kargs)
>>                    File "/usr/share/vdsm/logUtils.py", line 42, in
>>                 wrapper
>>                      res = f(*args, **kwargs)
>>                    File "/usr/share/vdsm/storage/hsm.py", line 923,
>>                 in connectStoragePool
>>                      masterVersion, options)
>>                    File "/usr/share/vdsm/storage/hsm.py", line 970,
>>                 in _connectStoragePool
>>                      res = pool.connect(hostID, scsiKey, msdUUID,
>>                 masterVersion)
>>                    File "/usr/share/vdsm/storage/sp.py", line 643, in
>>                 connect
>>                      self.__rebuild(msdUUID=msdUUID,
>>                 masterVersion=masterVersion)
>>                    File "/usr/share/vdsm/storage/sp.py", line 1167,
>>                 in __rebuild
>>                      self.masterDomain =
>>                 self.getMasterDomain(msdUUID=msdUUID,
>>                 masterVersion=masterVersion)
>>                    File "/usr/share/vdsm/storage/sp.py", line 1506,
>>                 in getMasterDomain
>>                      raise se.StoragePoolMasterNotFound(self.spUUID,
>>                 msdUUID)
>>                 StoragePoolMasterNotFound: Cannot find master domain:
>>                 'spUUID=f90a0d1c-06ca-11e2-a05b-00151712f280,
>>                 msdUUID=67534cca-1327-462a-b455-a04464084b31'
>>                 Thread-18::DEBUG::2013-01-23
>>                 15:50:42,887::task::852::TaskManager.Task::(_run)
>>                 Task=`08709e68-bcbc-40d8-843a-d69d4df40ac6`::Task._run:
>>                 08709e68-bcbc-40d8-843a-d69d4df40ac6
>>                 ('f90a0d1c-06ca-11e2-a05b-00151712f280', 2,
>>                 'f90a0d1c-06ca-11e2-a05b-00151712f280',
>>                 '67534cca-1327-462a-b455-a04464084b31', 433) {}
>>                 failed - stopping task
>>
>>                 This is with vdsm built from
>>                 commit25a2d8572ad32352227c98a86631300fbd6523c1
>>                 - DHC
>>
>>
>>                 On Wed, Jan 23, 2013 at 10:44 AM, Dead Horse <
>>                 deadhorseconsulting at gmail.com
>>                 <mailto:deadhorseconsulting at gmail.com>> wrote:
>>
>>                     VDSM was built from:
>>                     commit 166138e37e75767b32227746bb671b1dab9cdd5e
>>
>>                     Attached is the full vdsm log
>>
>>                     I should also note that from engine perspective
>>                     it sees the master
>>                     storage domain as locked and the others as unknown.
>>
>>
>>                     On Wed, Jan 23, 2013 at 2:49 AM, Dan Kenigsberg
>>                     <danken at redhat.com <mailto:danken at redhat.com>>wrote:
>>
>>                         On Tue, Jan 22, 2013 at 04:02:24PM -0600,
>>                         Dead Horse wrote:
>>
>>                             Any ideas on this one? (from VDSM log):
>>                             Thread-25::DEBUG::2013-01-22
>>                             15:35:29,065::BindingXMLRPC::914::vds::(wrapper)
>>                             client
>>
>>                         [3.57.111.30]::call
>>
>>                             getCapabilities with () {}
>>                             Thread-25::ERROR::2013-01-22
>>                             15:35:29,113::netinfo::159::root::(speed)
>>                             cannot read ib0 speed
>>                             Traceback (most recent call last):
>>                                File
>>                             "/usr/lib64/python2.6/site-packages/vdsm/netinfo.py",
>>                             line 155,
>>
>>                         in
>>
>>                             speed
>>                                  s =
>>                             int(file('/sys/class/net/%s/speed' %
>>                             dev).read())
>>                             IOError: [Errno 22] Invalid argument
>>
>>                             Causes VDSM to fail to attach storage
>>
>>
>>                         I doubt that this is the cause of the
>>                         failure, as vdsm has always
>>                         reported "0" for ib devices, and still is.
>>
>>         it happens only when you call to getCapabilities.. so it
>>         doesn't related to the flow, and it can't effect the storage.
>>         Dan: I guess this is not the issue but why is the IOError?
>>
>>
>>                         Does a former version works with your Engine?
>>                         Could you share more of your vdsm.log? I
>>                         suppose the culprit lies in one
>>                         one of the storage-related commands, not in
>>                         statistics retrieval.
>>
>>
>>                             Engine side sees:
>>                             ERROR
>>                             [org.ovirt.engine.core.bll.storage.NFSStorageHelper]
>>                             (QuartzScheduler_Worker-96) [553ef26e]
>>                             The connection with details
>>                             192.168.0.1:/ovirt/ds failed because of
>>                             error code 100 and error
>>
>>                         message
>>
>>                             is: general exception
>>                             2013-01-22 15:35:30,160 INFO
>>                             [org.ovirt.engine.core.bll.SetNonOperationalVdsCommand]
>>                             (QuartzScheduler_Worker-96) [1ab78378]
>>                             Running command:
>>                             SetNonOperationalVdsCommand internal:
>>                             true. Entities affected :  ID:
>>                             8970b3fe-1faf-11e2-bc1f-00151712f280
>>                             Type: VDS
>>                             2013-01-22 15:35:30,200 INFO
>>                             [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand]
>>                             (QuartzScheduler_Worker-96) [1ab78378] START,
>>                             SetVdsStatusVDSCommand(HostName = kezan,
>>                             HostId =
>>                             8970b3fe-1faf-11e2-bc1f-00151712f280,
>>                             status=NonOperational,
>>                             nonOperationalReason=STORAGE_DOMAIN_UNREACHABLE),
>>                             log id: 4af5c4cd
>>                             2013-01-22 15:35:30,211 INFO
>>                             [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand]
>>                             (QuartzScheduler_Worker-96) [1ab78378]
>>                             FINISH, SetVdsStatusVDSCommand,
>>
>>                         log
>>
>>                             id: 4af5c4cd
>>                             2013-01-22 15:35:30,242 ERROR
>>                             [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
>>                             (QuartzScheduler_Worker-96) [1ab78378]
>>                             Try to add duplicate audit log
>>                             values with the same name. Type:
>>                             VDS_SET_NONOPERATIONAL_DOMAIN. Value:
>>                             storagepoolname
>>
>>                             Engine = latest master
>>                             VDSM = latest master
>>
>>
>>                         Since "latest master" is an unstable
>>                         reference by definition, I'm sure
>>                         that History would thank you if you post the
>>                         exact version (git hash?)
>>                         of the code.
>>
>>                             node = el6
>>
>>
>>
>>
>>
>>
>>
>>
>>             _______________________________________________
>>             Users mailing list
>>             Users at ovirt.org <mailto:Users at ovirt.org>
>>             http://lists.ovirt.org/mailman/listinfo/users
>>
>>
>>
>>         -- 
>>         Yaniv Bronhaim.
>>         RedHat, Israel
>>         09-7692289
>>         054-7744187
>>
>>
>>
>
>
>
>
> _______________________________________________
> Users mailing list
> Users at ovirt.org
> http://lists.ovirt.org/mailman/listinfo/users


-- 
---
?? Shu Ming
Open Virtualization Engineerning; CSTL, IBM Corp.
Tel: 86-10-82451626  Tieline: 9051626 E-mail: shuming at cn.ibm.com or shuming at linux.vnet.ibm.com
Address: 3/F Ring Building, ZhongGuanCun Software Park, Haidian District, Beijing 100193, PRC

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.ovirt.org/pipermail/users/attachments/20130131/92547216/attachment-0001.html>


More information about the Users mailing list