yahoo-eng-team team mailing list archive

[Doug Hellmann <doug@xxxxxxxxxxxxxxxx>]

** No longer affects: oslo

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1273478

Title:
  NetworkInfoAsyncWrapper __str__ can cause deadlock when called from a
  log message

Status in OpenStack Compute (Nova):
  Fix Released

Bug description:
  CPython logging library generates the string representation of the
  message to log under a lock.

      def handle(self, record):
          """
          Conditionally emit the specified logging record.

          Emission depends on filters which may have been added to the handler.
          Wrap the actual emission of the record with acquisition/release of
          the I/O thread lock. Returns whether the filter passed the record for
          emission.
          """
          rv = self.filter(record)
          if rv:
              self.acquire()
              try:
                  self.emit(record)
              finally:
                  self.release()
          return rv

  
  Nova will use the __str__ method of the NetworkInfoAsyncWrapper when logging a message as in:

  nova/virt/libvirt/driver.py:to_xml()

          LOG.debug(_('Start to_xml instance=%(instance)s '
                      'network_info=%(network_info)s '
                      'disk_info=%(disk_info)s '
                      'image_meta=%(image_meta)s rescue=%(rescue)s'
                      'block_device_info=%(block_device_info)s'),
                    {'instance': instance, 'network_info': network_info,
                     'disk_info': disk_info, 'image_meta': image_meta,
                     'rescue': rescue, 'block_device_info': block_device_info})

  Currently this causes the __str__ method to be called under the
  logging lock:

    File "/usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py", line 3058, in to_xml
      'rescue': rescue, 'block_device_info': block_device_info})
    File "/usr/lib/python2.7/logging/__init__.py", line 1412, in debug
      self.logger.debug(msg, *args, **kwargs)
    File "/usr/lib/python2.7/logging/__init__.py", line 1128, in debug
      self._log(DEBUG, msg, args, **kwargs)
    File "/usr/lib/python2.7/logging/__init__.py", line 1258, in _log
      self.handle(record)
    File "/usr/lib/python2.7/logging/__init__.py", line 1268, in handle
      self.callHandlers(record)
    File "/usr/lib/python2.7/logging/__init__.py", line 1308, in callHandlers
      hdlr.handle(record)
    File "/usr/lib/python2.7/logging/__init__.py", line 748, in handle
      self.emit(record)
    File "/usr/lib/python2.7/logging/handlers.py", line 414, in emit
      logging.FileHandler.emit(self, record)
    File "/usr/lib/python2.7/logging/__init__.py", line 930, in emit
      StreamHandler.emit(self, record)
    File "/usr/lib/python2.7/logging/__init__.py", line 846, in emit
      msg = self.format(record)
    File "/usr/lib/python2.7/logging/__init__.py", line 723, in format
      return fmt.format(record)
    File "/usr/lib/python2.7/dist-packages/nova/openstack/common/log.py", line 517, in format
      return logging.Formatter.format(self, record)
    File "/usr/lib/python2.7/logging/__init__.py", line 464, in format
      record.message = record.getMessage()
    File "/usr/lib/python2.7/logging/__init__.py", line 328, in getMessage
      msg = msg % self.args
    File "/usr/lib/python2.7/dist-packages/nova/network/model.py", line 383, in __str__
      return self._sync_wrapper(fn, *args, **kwargs)

  This then waits for an eventlet to complete. This eventlet may itself
  attempt to use a log message as it executes.

  This sequence of operations can produce a deadlock between a greenlet
  thread waiting for the async operation to finish and the async job
  itself, if it decides to log a message.

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1273478/+subscriptions