Esempio n. 1
0
 def _start_child_logger(self):
     self._stop_child_logger()
     self.child_logs_queue = multiprocessing.Queue()
     self.child_logger = LogsReceiver(self.getName(), self.child_logs_queue)
     self.child_logger.start()
     if self.child_logger is None:
         logger = logging.getLogger(u'FR.WorkerChild of %s' % self.getName())
         self.child_logger = {
             'info': logger.info,
             'debug': logger.debug,
             'warning': logger.warning,
             'error': logger.error,
             'critical': logger.critical
         }
Esempio n. 2
0
 def _start_child_logger(self):
     self._stop_child_logger()
     self.child_logs_queue = multiprocessing.Queue()
     self.child_logger = LogsReceiver(self.getName(), self.child_logs_queue)
     self.child_logger.start()
     if self.child_logger is None:
         logger = logging.getLogger(u'FR.WorkerChild of %s' % self.getName())
         self.child_logger = {
             'info': logger.info,
             'debug': logger.debug,
             'warning': logger.warning,
             'error': logger.error,
             'critical': logger.critical
         }
Esempio n. 3
0
class Worker(Thread):
    '''A worker takes something to do and does it, and then again takes
    something to do etc.
    '''

    def __init__(self,
                 warebox,
                 operation_queue,
                 server_session,
                 cfg,
                 cryptoAdapter,
                 worker_pool):
        """
        @param warebox:
                    Instance of filerockclient.warebox.Warebox.
        @param cfg:
                    Instance of filerockclient.config.ConfigManager.
        @param operation_queue:
                    A threading queue, where worker receives the operations
        @param worker_pool:
                    Instance of filerockclient.workers.worker.Worker
        """
        Thread.__init__(self, name=self.__class__.__name__)
        self.cfg = cfg
        self.operation_queue = operation_queue
        self._server_session = server_session
        self.warebox = warebox
        self.child = None

        self.input_queue = None
        self.communicationQueue = None
        self.child_logger = None
        self.child_logs_queue = None
        self.cryptoAdapter = cryptoAdapter
        self.integrity_manager = IntegrityManager(None)

        self._worker_pool = worker_pool
        self.must_die = threading.Event()
        self.last_send = datetime.now()
        self.communicationQueue = None
        self.child_logs_queue = None

    def run(self):
        """
        Serves file operations until termination request is received
        """
        try:
            self.name += "_%s" % self.ident
            self.logger = logging.getLogger("FR.%s" % self.getName())
            self.logger.debug(u'Started.')
            while not self._termination_requested():
                self._serve_file_operations()
            self.logger.debug(u"I'm terminated.")
        finally:
            self._terminate_child()

    def _serve_file_operations(self):
        """
        Blocks on operation queue until a message is received

        If the message is a POISON_PILL the worker terminate it self
        If the message is a non aborted file operation,
        an abort handler is registered to it and the operation is handled
        """
        try:
            file_operation = self.operation_queue.get()
            self.warebox._check_blacklisted_dir()
            if file_operation == 'POISON_PILL':
                self._on_poison_pill()
            elif file_operation.is_aborted():
                self.logger.debug(u"Got an already aborted operation, "
                                  "giving up: %s" % file_operation)
            else:
                try:
                    self.logger.debug(u"Got an operation to handle: %s"
                                      % file_operation)
                    file_operation.register_abort_handler(self.on_operation_abort)
                    self._handle_file_operation(file_operation)
                except Exception as e:
                    self.logger.error(
                        u"Some problem occurred with the operation : %r" % e)
                    raise e
        finally:
            self.logger.debug("Releasing a worker")
            self._worker_pool.release_worker()

    def _handle_file_operation(self, file_operation):
        if file_operation.verb == 'UPLOAD':
            self._handle_upload_file_operation(file_operation)
        elif file_operation.verb == 'DOWNLOAD':
            self._handle_download_file_operation(file_operation)
        elif file_operation.verb == 'DELETE_LOCAL':
            self._handle_delete_local_file_operation(file_operation)
        elif file_operation.verb == 'CREATE_DIRECTORIES':
            self._handle_operation_create_directories(file_operation)
        elif file_operation.verb == 'RESOLVE_DELETION_CONFLICTS':
            self._handle_operation_resolve_deletion_conflicts(file_operation)
        else:
            self.logger.warning(u"I should not handle a '%s' operation! "
                                "I'm rejecting it", file_operation.verb)
            file_operation.reject()

    def _send_percentage(self, file_operation, status, percentage):
        now = datetime.now()
        delta = now - self.last_send
        if ((delta.seconds + delta.microseconds/1000000.) > 0.5) or (percentage == 100):
            file_operation.notify_pathname_status_change(status, {'percentage': percentage})
            self.last_send = now

    def _handle_network_transfer_operation(self, file_operation):
        '''By locking we mantain the following invariant: if the
        EventQueue tries to abort this operation due to a conflicting
        operation, then EventQueue waits until this operation either
        aborts or completes.
        This preserves the ordering of execution for the conflicting
        operations - that is, the EventQueue doesn't emit
        the conflicting operation while this one is still working.
        '''

        with file_operation.lock:
            if not file_operation.is_aborted():
                self.logger.debug(u"Starting child process to handle file"
                                  " operation: %s" % file_operation)
                try:
                    self._spawn_child(file_operation)
                    self.input_queue.put(('FileOperation', file_operation))
                except Exception as e:
                    self.logger.error(
                        u"Could not spawn a child process: %r" % e)
                    raise OperationRejection(file_operation)
            else:
                self.logger.debug(u"Got an already aborted operation, "
                                  "giving up: %s" % file_operation)
                return False

        if file_operation.verb == 'UPLOAD':
            status = PStatuses.UPLOADING
        else:
            status = PStatuses.DOWNLOADING

        self._send_percentage(file_operation, status, 0)
        termination = False
        max_retry = 3

        while not termination:
            message, content = self.communicationQueue.get()
            self.logger.debug(u'Worker send back %s with content %s'
                              % (message, content))

            if message == 'completed':
                termination = True
                if file_operation.verb == 'DOWNLOAD':
                    return {'actual_etag': content['actual_etag']}
                else:
                    return True

            elif message == 'interrupted':
                self.logger.debug(u"Child has been terminated by "
                                  "Software Operation: %s"
                                  % file_operation)
                file_operation.abort()
                termination = True
                return False

            elif message == 'failed':
                self.logger.error(u"Child has been terminated, "
                                  "Assuming failure for operation: %s"
                                  % file_operation)
                max_retry -= 1
                if max_retry == 0:
                    raise OperationRejection(file_operation)
                self.input_queue.put(('FileOperation', file_operation))

            elif message == 'percentage':
                self._send_percentage(file_operation, status, content)

            elif message == 'log':
                level, msg = content
                self.child_logger[level](msg)

            elif message == 'ShuttingDown':
                self.logger.debug(u"Get a shutting down message from process")
                termination = True
                return False

            elif message == 'DIED':
                self.child = None
                termination = True
                raise OperationRejection(file_operation)

    def _handle_upload_file_operation(self, operation):
        try:
            success = self._handle_network_transfer_operation(operation)
            if success:
                CryptoUtils.clean_env(operation, self.logger)
                self.logger.debug(u"Operation has been completed "
                                  "successfully: %s" % operation)
                self.logger.info(u'Synchronized pathname: %s "%s", which '
                                 'will be persisted after a commit'
                                 % (operation.verb, operation.pathname))
                operation.notify_pathname_status_change(PStatuses.UPLOADED,
                                                        {'percentage': 100})
                operation.complete()

        except Exception as e:
            self.logger.error(u"Error while uploading: %r."
                              " Rejecting the operation: %s" % (e, operation))
            operation.reject()

    def _handle_operation_create_directories(self, task):
        operations = sorted(task.operations, key=lambda op: op.pathname)
        actual_etag = 'd41d8cd98f00b204e9800998ecf8427e'

        for operation in operations:

            # Check integrity
            operation.notify_pathname_status_change(PStatuses.DOWNLOADING)
            res = self._check_download_integrity(operation, actual_etag)
            if not res['valid']:
                # Detected an integrity error. Badly bad.
                self._server_session.signal_download_integrity_error(
                    operation, res['reason'],
                    res['expected_etag'], res['expected_basis'],
                    res['actual_etag'], res['computed_basis'])
                return

            # The directory is valid, create it
            self.warebox.make_directory(operation.pathname)
            lmtime = self.warebox.get_last_modification_time(operation.pathname)
            operation.lmtime = lmtime
            operation.notify_pathname_status_change(PStatuses.ALIGNED)
            operation.complete()
            self.logger.info(u'Synchronized pathname: %s "%s"'
                             % (operation.verb, operation.pathname))
            self.logger.debug(u"Operation has been completed "
                              "successfully: %s" % operation)

        task.complete()

    def _handle_download_file_operation(self, operation):
        try:
            # Note: it is a normal file, not a directory
            CryptoUtils.set_temp_file(operation, self.cfg)
            success = self._handle_network_transfer_operation(operation)

            if success:

                actual_etag = success['actual_etag']
                res = self._check_download_integrity(operation, actual_etag)
                if not res['valid']:
                    # Detected an integrity error. Badly bad.
                    self._server_session.signal_download_integrity_error(
                        operation, res['reason'],
                        res['expected_etag'], res['expected_basis'],
                        res['actual_etag'], res['computed_basis'])
                    return

                if operation.to_decrypt:
                    # We have not finished yet, leaving the rest to decrypter.
                    # Note: the decrypter duplicates the following ending logic
                    self.cryptoAdapter.put(operation)
                    return

                # It is a valid cleartext file, move it to the warebox
                self.warebox.move(operation.temp_pathname,
                                  operation.pathname,
                                  operation.conflicted)

                self.logger.debug(u"Operation has been completed "
                                  "successfully: %s" % operation)
                self.logger.info(u'Synchronized pathname: %s "%s"'
                                 % (operation.verb, operation.pathname))

                lmtime = self.warebox.get_last_modification_time(operation.pathname)
                operation.lmtime = lmtime
                operation.notify_pathname_status_change(PStatuses.ALIGNED)
                operation.complete()

        except Exception as e:
            self.logger.error(u"Error while downloading: %r."
                              " Rejecting the operation: %s" % (e, operation))
            self.logger.error(u"Stacktrace: %r" % traceback.format_exc())
            operation.reject()

        finally:
            # Just in case the move had failed for any reason
            if not operation.to_decrypt:
                if operation.temp_pathname is not None \
                and os.path.exists(operation.temp_pathname):
                    _try_remove(operation.temp_pathname, self.logger)

    def _check_download_integrity(self, operation, actual_etag):
        pathname = operation.pathname
        proof = operation.download_info['proof']
        basis = operation.download_info['trusted_basis']

        self.integrity_manager.trusted_basis = basis

        result = {}
        result['valid'] = None
        result['reason'] = None
        result['expected_etag'] = operation.storage_etag
        result['expected_basis'] = basis
        result['actual_etag'] = actual_etag
        result['computed_basis'] = None

        if operation.storage_etag != actual_etag:
            # Note: the etag inside the proof will be
            # checked by the integrity manager.
            self.logger.debug(
                u"Invalid etag of download operation. "
                "Expected etag %s but found %s. %s"
                % (operation.storage_etag, actual_etag, operation))
            result['valid'] = False
            result['reason'] = "Expected etag different from actual etag"
            return result

        try:
            self.integrity_manager.addOperation('DOWNLOAD',
                                                pathname,
                                                proof,
                                                actual_etag)
            result['valid'] = True
            result['computed_basis'] = basis

        except MalformedProofException as e:
            self.logger.debug(u"Invalid proof of download operation: "
                              "%s. %r, %r" % (e, operation, proof))
            self.logger.debug(traceback.format_exc())
            result['valid'] = False
            result['reason'] = "%s" % e

        except WrongBasisFromProofException as e:
            self.logger.debug(u"Integrity check of download operation failed."
                              "Basis %s was expected but the proof computed "
                              "%s. Error details: %s. %r, %r" %
                              (basis, e.operation_basis, e, operation, proof))
            self.logger.debug(traceback.format_exc())
            result['valid'] = False
            result['reason'] = "%s" % e
            result['computed_basis'] = e.operation_basis

        except Exception as e:
            self.logger.debug(u"Integrity check of download operation failed"
                              " with unknown reason: %s. %r, %r"
                              % (e, operation, proof))
            self.logger.debug(traceback.format_exc())
            result['valid'] = False
            result['reason'] = "%s" % e

        finally:
            self.integrity_manager.clear()

        return result

    def _handle_delete_local_file_operation(self, task):
        pathnames = sorted(task.pathname2proof.keys())
        #self.logger.debug("Going to delete pathnames: %s" % pathnames)

        for pathname in pathnames:
            basis = task.trusted_basis
            proof = task.pathname2proof[pathname]
            res = self._check_deletelocal_integrity(pathname, proof, basis)
            if not res['valid']:
                # Detected an integrity error. Badly bad.
                self._server_session.signal_deletelocal_integrity_error(
                    pathname, proof, res['reason'],
                    res['expected_basis'], res['computed_basis'])
                return

        roots = {}
        for pathname in pathnames:
            found_ancestor = False
            for root in roots:
                if pathname.startswith(root):
                    found_ancestor = True
                    break
            if not found_ancestor:
                roots[pathname] = True

        try:
            for pathname in roots.iterkeys():
                self.warebox.delete_tree(pathname)
        except Exception as e:
            self.logger.error(
                u"Caught an operating system exception while "
                u"modifying the filesystem. Are you locking the Warebox? % r"
                % e)
            raise

        task.complete()

    def _check_deletelocal_integrity(self, pathname, proof, trusted_basis):
        self.integrity_manager.trusted_basis = trusted_basis

        result = {}
        result['valid'] = None
        result['reason'] = None
        result['expected_basis'] = trusted_basis
        result['computed_basis'] = None

        try:
            self.integrity_manager.addOperation('DELETE_LOCAL',
                                                pathname,
                                                proof,
                                                None)
            result['valid'] = True
            result['computed_basis'] = trusted_basis

        except MalformedProofException as e:
            self.logger.debug(u"Invalid proof of delete_local operation: "
                              "%s. %s, %s" % (e, pathname, proof.raw))
            self.logger.debug(traceback.format_exc())
            result['valid'] = False
            result['reason'] = "%s" % e

        except WrongBasisFromProofException as e:
            self.logger.debug(u"Integrity check of delete_local operation failed."
                              "Basis %s was expected but the proof computed "
                              "%s. Error details: %s. %r, %r" %
                              (trusted_basis, e.operation_basis, e, pathname, proof.raw))
            self.logger.debug(traceback.format_exc())
            result['valid'] = False
            result['reason'] = "%s" % e
            result['computed_basis'] = e.operation_basis

        except Exception as e:
            self.logger.debug(u"Integrity check of delete_local operation failed"
                              " with unknown reason: %s. %r, %r"
                              % (e, pathname, proof.raw))
            self.logger.debug(traceback.format_exc())
            result['valid'] = False
            result['reason'] = "%s" % e

        finally:
            self.integrity_manager.clear()

        return result

    def _find_new_name(self, pathname):
        # TODO: try harder in finding a name that is available
        curr_time = datetime.now().strftime('%Y-%m-%d %H_%M_%S')
        suffix = ' (Conflicted on %s)' % curr_time
        if pathname.endswith('/'):
            new_pathname = pathname[:-1] + suffix + '/'
        else:
            basename, ext = os.path.splitext(pathname)
            new_pathname = basename + suffix + ext
        return new_pathname

    def _rename_conflicting_pathname(self, pathname, prefix=None):
        new_pathname = self.warebox.rename(pathname, pathname, prefix)
        return new_pathname

    def _handle_operation_resolve_deletion_conflicts(self, task):
        """Solve deletion conflicts by renaming the local file to a new
        pathname. The old pathname will result implicitly deleted.

        Side effect on Content_to_upload to add the renamed files.

        Deletion conflicts are tough to resolve. A conflicting pathname:
        a) has been deleted by the server
        b) has an ancestor folder that has been deleted by the server
        c) both
        It must be checked if it's safe leaving the file in its original
        folder (that is, if it still exists).
        """
        conflicts = task.deletion_conflicts
        content_to_delete_locally = task.content_to_delete_locally

        for pathname in conflicts:
            basis = task.trusted_basis
            proof = task.pathname2proof[pathname]
            res = self._check_deletelocal_integrity(pathname, proof, basis)
            if not res['valid']:
                # Detected an integrity error. Badly bad.
                self._server_session.signal_deletelocal_integrity_error(
                    pathname, proof, res['reason'],
                    res['expected_basis'], res['computed_basis'])
                return

        try:
            backupped_folders = {}
            for pathname in conflicts:
                missing_ancestor_folders = filter(lambda p: pathname.startswith(p), content_to_delete_locally)
                # Is it safe leaving the file in its original folder?
                if len(missing_ancestor_folders) > 0:
                    # No, it's been deleted. Backup the whole deleted subtree
                    missing_ancestor_folders = sorted(missing_ancestor_folders)
                    highest_missing_folder = missing_ancestor_folders[0]
                    if not highest_missing_folder in backupped_folders:
                        backup_folder = self._find_new_name(highest_missing_folder)
                        self.warebox.make_directory(backup_folder)
                        backupped_folders[highest_missing_folder] = backup_folder
                    backup_folder = backupped_folders[highest_missing_folder]
                    new_pathname = pathname.replace(highest_missing_folder, backup_folder, 1)
                    self.warebox.make_directories_to(new_pathname)
                    if not self.warebox.is_directory(new_pathname):
                        self.warebox.rename(pathname, new_pathname)
                else:
                    # Yes, just rename the file
                    new_pathname = self._rename_conflicting_pathname(pathname, 'Deleted')
                    self.logger.warning(
                        u"Conflict detected for pathname %r, which has been "
                        u"remotely deleted. Moved the local copy to: %r"
                        % (pathname, new_pathname))

            task.complete()

        except Exception:
            self.logger.error(
                u"Caught an operating system exception while modifying the "
                u"filesystem. Are you locking the Warebox?")
            raise

    def _start_child_logger(self):
        self._stop_child_logger()
        self.child_logs_queue = multiprocessing.Queue()
        self.child_logger = LogsReceiver(self.getName(), self.child_logs_queue)
        self.child_logger.start()
        if self.child_logger is None:
            logger = logging.getLogger(u'FR.WorkerChild of %s' % self.getName())
            self.child_logger = {
                'info': logger.info,
                'debug': logger.debug,
                'warning': logger.warning,
                'error': logger.error,
                'critical': logger.critical
            }

    def _stop_child_logger(self):
        if self.child_logger is not None:
            self.child_logger.stop()
            self.child_logs_queue.put(('log', ('debug', 'Die please!')))
            self.child_logger.join()
            self.child_logger = None

        if self.child_logs_queue is not None:
            self.child_logs_queue.close()
            self.child_logs_queue.join_thread()
            self.child_logs_queue = None

    def _create_multiprocessing_queues(self):
        self._destroy_multiprocessing_queues()
        self.input_queue = Queue.Queue()
        self.communicationQueue = Queue.Queue()

    def _destroy_multiprocessing_queue(self, queue):
        if queue is not None:
            while not queue.empty():
                queue.get_nowait()
#             queue.close()
#             queue.join_thread()
            queue = None

    def _destroy_multiprocessing_queues(self):
        self._destroy_multiprocessing_queue(self.input_queue)
        self._destroy_multiprocessing_queue(self.communicationQueue)

    def _spawn_child(self, file_operation):
        if self.child is None or not self.child.is_alive():
#             self.terminationEvent = multiprocessing.Event()
            self.terminationEvent = threading.Event()
            self._create_multiprocessing_queues()
            self._start_child_logger()
            try:
                self.logger.debug(u"Allocating child process to handle file "
                                  "operation: %s" % file_operation)
                self.child = WorkerChild(self.warebox,
                                         self.input_queue,
                                         self.communicationQueue,
                                         self.terminationEvent,
                                         self._send_percentage,
                                         #self.child_logs_queue,
                                         self.cfg,
                                         self._worker_pool)

                self.child.start()
                self.logger.debug(u"Child process Started to handle file "
                                  "operation: %s" % file_operation)
            except Exception:
                self._stop_child_logger()
                raise

    def on_operation_abort(self, file_operation):
        self.logger.debug(u'Abort detected for the operation I am handling: '
                          '%s. Terminating child process...' % file_operation)
        self.abort_operation()

    def abort_operation(self):
        if self.child is not None and self.child.is_alive():
            try:
                if self.terminationEvent is not None:
                    self.terminationEvent.set()
#                 else:
#                     self.child.terminate()
            except:
                pass

    def _terminate_child(self):
        self.stop_network_transfer()
        if self.child is not None:
            self.input_queue.put(('PoisonPill', None))
            self.child.join(5)
            self.child = None

    def _clean_env(self):
        self._terminate_child()
        self._stop_child_logger()
        self._destroy_multiprocessing_queues()

    def _on_poison_pill(self):
        self.logger.debug(u"Got poison pill.")
        self.must_die.set()
        self._clean_env()

    def terminate(self):
        '''
        Signal the worker that the time has come.
        '''
        self.abort_operation()

    def stop_network_transfer(self):
        self.abort_operation()

    def _termination_requested(self):
        return self.must_die.wait(0.01)
Esempio n. 4
0
class Worker(Thread):
    ''' A worker takes something to do and does it, and then again takes something to do etc.'''

    def __init__(self,
                 warebox,
                 operation_queue,
                 cfg,
                 worker_pool):
        """
        @param warebox:
                    Instance of filerockclient.warebox.Warebox.
        @param cfg:
                    Instance of filerockclient.config.ConfigManager.
        @param operation_queue:
                    A threading queue, where worker receives the operations
        @param worker_pool:
                    Instance of filerockclient.workers.worker.Worker
        """
        Thread.__init__(self, name=self.__class__.__name__)
        self.cfg = cfg
        self.operation_queue = operation_queue
        self.warebox = warebox
        self.child = None

        self.input_queue = None
        self.communicationQueue = None
        self.child_logger = None
        self.child_logs_queue = None

        self._worker_pool = worker_pool
        self.must_die = threading.Event()
        self.last_send = datetime.now()
        self.communicationQueue = None
        self.child_logs_queue = None

    def run(self):
        """
        Serves file operations until termination request is received
        """
        try:
            self.name += "_%s" % self.ident
            self.logger = logging.getLogger("FR.%s" % self.getName())
            self.logger.debug(u'Started.' )
            while not self._termination_requested():
                self._serve_file_operations()
            self.logger.debug(u"I'm terminated.")
        finally:
            self._terminate_child()

    def _serve_file_operations(self):
        """
        Blocks on operation queue until a message is received

        If the message is a POISON_PILL the worker terminate it self
        If the message is a non aborted file operation,
        an abort handler is registered to it and the operation is handled
        """
        try:
            file_operation = self.operation_queue.get()
            if file_operation == 'POISON_PILL':
                self.__on_poison_pill()
            elif file_operation.is_aborted():
                self.logger.debug(u"Got an already aborted operation, giving up: %s", file_operation)
            else:
                try:
                    self.logger.debug(u"Got an operation to handle: %s", file_operation)
                    file_operation.register_abort_handler(self.on_operation_abort)
                    self._handle_file_operation(file_operation)
                except Exception as e:
                    self.logger.error(u"Some problem occurred with the operation : %r" % e)
                    raise e
        except KeyboardInterrupt:
            pass
        finally:
            self.logger.debug("Releasing a worker")
            self._worker_pool.release_worker()

    def _handle_file_operation(self, file_operation):
        if file_operation.verb == 'UPLOAD':
            self._handle_upload_file_operation(file_operation)
        elif file_operation.verb == 'DOWNLOAD':
            self._handle_download_file_operation(file_operation)
        elif file_operation.verb == 'DELETE_LOCAL':
            self._handle_delete_local_file_operation(file_operation)
        else:
            self.logger.warning(u"I should not handle a '%s' operation! I'm rejecting it", file_operation.verb)
            file_operation.reject()

    def __get_temp_file(self, file_operation):
        if file_operation.verb == 'DOWNLOAD':
            temp_dir = self.cfg.get('User', 'temp_dir')
            temp_fd, temp_pathname = mkstemp(dir=temp_dir)
            file_operation.temp_pathname = temp_pathname
            file_operation.temp_fd = temp_fd

    def __clean_temp_file(self, file_operation):
        if file_operation.verb == 'DOWNLOAD':
            if os.path.exists(file_operation.temp_pathname):
                try:
                    os.close(file_operation.temp_fd)
                    os.remove(file_operation.temp_pathname)
                    self.logger.debug(u'Temp file %s deleted' % file_operation.temp_pathname)
                except:
                    pass

    def __send_percentage(self, file_operation, status, percentage):
        now = datetime.now()
        delta = now - self.last_send
        if (delta.seconds + delta.microseconds/1000000.) > 0.5:
            file_operation.notify_pathname_status_change(status, {'percentage': percentage})
            self.last_send = now

    def __on_operation_complete(self, file_operation):
        self.logger.debug(u"Operation has been completed successfully: %s", file_operation)
        # TODO: this "if" here is ugly
        if file_operation.verb == 'DOWNLOAD' and file_operation.to_decrypt:
            file_operation.warebox_etag = self.warebox.compute_md5_hex(file_operation.pathname)
            file_operation.warebox_size = self.warebox.get_size(file_operation.pathname)
        if file_operation.verb == 'UPLOAD':
            self.logger.info(u'Synchronized pathname: %s "%s", which will be persisted after a commit' % (file_operation.verb, file_operation.pathname))
            file_operation.notify_pathname_status_change(PStatuses.UPLOADED, {'percentage': 100})
        else:
            self.logger.info(u'Synchronized pathname: %s "%s"' % (file_operation.verb, file_operation.pathname))
            lmtime = self.warebox.get_last_modification_time(file_operation.pathname)
            file_operation.lmtime = lmtime
            file_operation.notify_pathname_status_change(PStatuses.ALIGNED)
        file_operation.complete()


    def _handle_network_transfer_operation(self, file_operation):
        '''By locking we mantain the following invariant: if the EventQueue tries to abort this operation due to
           a conflicting operation, then EventQueue waits until this operation either aborts or completes.
           This preserves the ordering of execution for the conflicting operations - that is, the EventQueue doesn't emit
           the conflicting operation while this one is still working.'''

        with file_operation.lock:
            if not file_operation.is_aborted():
                self.logger.debug(u"Starting child process to handle file operation: %s", file_operation)
                try:
                    self._spawn_child(file_operation)
                    self.input_queue.put(('FileOperation',file_operation))
                except Exception as e:
                    self.logger.error(u"Could not spawn a child process: %r" % e)
                    raise OperationRejection(file_operation)
            else:
                self.logger.debug(u"Got an already aborted operation, giving up: %s", file_operation)
                return

        if file_operation.verb == 'UPLOAD':
            status = PStatuses.UPLOADING
        else:
            status = PStatuses.DOWNLOADING

        self.__send_percentage(file_operation, status, 0)
        termination = False
        max_retry = 3
        while not termination:
            message, content = self.communicationQueue.get()
#            self.logger.debug('Worker send back %s with content %s' % (message, content))
            if message == 'result':
                CryptoUtils.clean_env(file_operation, self.logger)
                if content == 'completed':
                    self.__send_percentage(file_operation, status, 100)
                    self.__on_operation_complete(file_operation)
                    termination = True
                elif content == 'interrupted':
                    self.logger.debug(u"Child has been terminated by Software Operation: %s", file_operation)
                    file_operation.abort()
                    termination = True
                elif content == 'failed':
                    self.logger.error(u"Child has been terminated, Assuming failure for operation: %s", file_operation)
                    max_retry -= 1
                    if max_retry == 0:
                        raise OperationRejection(file_operation)
                    self.input_queue.put(('FileOperation',file_operation))
            elif message == 'percentage':
                self.__send_percentage(file_operation, status, content)
            elif message == 'log':
                level, msg = content
                self.child_logger[level](msg)
            elif message == 'ShuttingDown':
                self.logger.debug("Get a shutting down message from process")
                termination = True
            elif message == 'DIED':
                file_operation.reject()
                self.child=None
                termination = True
        self.logger.debug('Quit from _handle_network_transfer_operation method')


    def _handle_upload_file_operation(self, operation):
        try:
            self._handle_network_transfer_operation(operation)
        except Exception as e:
            self.logger.error(u"Error while uploading: %r." % e +
                " Rejecting the operation: %s" % operation)
            operation.reject()

    def _handle_download_file_operation(self, operation):
        try:
            if operation.is_directory():
                operation.notify_pathname_status_change(PStatuses.DOWNLOADING)
                if operation.is_leaf:
                    self.warebox.make_directories_to(operation.pathname)
                lmtime = self.warebox.get_last_modification_time(operation.pathname)
                operation.lmtime = lmtime
                operation.notify_pathname_status_change(PStatuses.ALIGNED)
                operation.complete()
                self.logger.info(u'Synchronized pathname: %s "%s"'
                    % (operation.verb, operation.pathname))
                self.logger.debug(u"Operation has been completed " +
                    "successfully: %s", operation)
            else:
                self.warebox.make_directories_to(operation.pathname)
                CryptoUtils.get_temp_file(operation, self.cfg)
                self._handle_network_transfer_operation(operation)

        except Exception as e:
            self.logger.error(u"Error while downloading: %r." % e +
                " Rejecting the operation: %s" % operation)
            operation.reject()

    def _handle_delete_local_file_operation(self, file_operation):
        # Currently DELETE_LOCAL operations aren't handled by Workers
        raise Exception('Unexpected verb for operation: %s' % file_operation)


    def __start_child_logger(self):
        self.__stop_child_logger()
        self.child_logs_queue = multiprocessing.Queue()
#         self.child_logs_queue = Queue.Queue()
        self.child_logger = LogsReceiver(self.getName(), self.child_logs_queue)
        self.child_logger.start()
        if self.child_logger == None:
            logger = logging.getLogger('FR.WorkerChild of %s' % self.getName())
            self.child_logger = {
                    'info': logger.info,
                    'debug': logger.debug,
                    'warning': logger.warning,
                    'error': logger.error,
                    'critical': logger.critical
                    }

    def __stop_child_logger(self):
#         pass
        if self.child_logger is not None:
            self.child_logger.stop()
            self.child_logs_queue.put(('log',('debug','Die please!')))
            self.child_logger.join()
            self.child_logger = None
            
        if self.child_logs_queue is not None:
            self.child_logs_queue.close()
            self.child_logs_queue.join_thread()
            self.child_logs_queue = None



    def __create_multiprocessing_queues(self):
        self.__destroy_multiprocessing_queues()
        self.input_queue = multiprocessing.Queue()
        self.communicationQueue = multiprocessing.Queue()

    def __destroy_multiprocessing_queue(self, queue):
        if queue is not None:
            queue.close()
            queue.join_thread()
            queue = None

    def __destroy_multiprocessing_queues(self):
        self.__destroy_multiprocessing_queue(self.input_queue)
        self.__destroy_multiprocessing_queue(self.communicationQueue)

    def _spawn_child(self, file_operation):
        if self.child is None or not self.child.is_alive():
            self.terminationEvent = multiprocessing.Event()
            self.__create_multiprocessing_queues()
            self.__start_child_logger()
            try:
                self.logger.debug(u"Allocating child process to handle file operation: %s", file_operation)
                self.child = WorkerChild(self.input_queue,
                                         self.communicationQueue,
                                         self.terminationEvent,
#                                         self.communicationQueue,
                                         self.child_logs_queue,
                                         self.cfg)
                self.child.start()
                self.logger.debug(u"Child process Started to handle file operation: %s", file_operation)
            except Exception:
                self.__stop_child_logger()
                raise

    def on_operation_abort(self, file_operation):
        self.logger.debug(u'Abort detected for the operation I am handling: %s. Terminating child process...' % (file_operation))
        self.abort_operation()

    def abort_operation(self):
        if self.child != None and self.child.is_alive():
            try:
                if self.terminationEvent is not None:
                    self.terminationEvent.set()
                else:
                    self.child.terminate()
            except:
                pass

    def _terminate_child(self):
        self.stop_network_transfer()
        if self.child is not None:
            self.input_queue.put(('PoisonPill', None))
            self.child.join(5)
            self.child = None

    def _clean_env(self):
        self._terminate_child()
        self.__stop_child_logger()
        self.__destroy_multiprocessing_queues()

    def __on_poison_pill(self):
        self.logger.debug(u"Got poison pill.")
        self.must_die.set()
        self._clean_env()

    def terminate(self):
        '''
        Signal the worker that the time has come.
        '''
        self.abort_operation()

    def stop_network_transfer(self):
        self.abort_operation()

    def _termination_requested(self):
        return self.must_die.wait(0.01)
Esempio n. 5
0
class Worker(Thread):
    '''A worker takes something to do and does it, and then again takes
    something to do etc.
    '''

    def __init__(self,
                 warebox,
                 operation_queue,
                 server_session,
                 cfg,
                 cryptoAdapter,
                 worker_pool):
        """
        @param warebox:
                    Instance of filerockclient.warebox.Warebox.
        @param cfg:
                    Instance of filerockclient.config.ConfigManager.
        @param operation_queue:
                    A threading queue, where worker receives the operations
        @param worker_pool:
                    Instance of filerockclient.workers.worker.Worker
        """
        Thread.__init__(self, name=self.__class__.__name__)
        self.cfg = cfg
        self.operation_queue = operation_queue
        self._server_session = server_session
        self.warebox = warebox
        self.child = None

        self.input_queue = None
        self.communicationQueue = None
        self.child_logger = None
        self.child_logs_queue = None
        self.cryptoAdapter = cryptoAdapter
        self.integrity_manager = IntegrityManager(None)

        self._worker_pool = worker_pool
        self.must_die = threading.Event()
        self.last_send = datetime.now()
        self.communicationQueue = None
        self.child_logs_queue = None

    def run(self):
        """
        Serves file operations until termination request is received
        """
        try:
            self.name += "_%s" % self.ident
            self.logger = logging.getLogger("FR.%s" % self.getName())
            self.logger.debug(u'Started.')
            while not self._termination_requested():
                self._serve_file_operations()
            self.logger.debug(u"I'm terminated.")
        finally:
            self._terminate_child()

    def _serve_file_operations(self):
        """
        Blocks on operation queue until a message is received

        If the message is a POISON_PILL the worker terminate it self
        If the message is a non aborted file operation,
        an abort handler is registered to it and the operation is handled
        """

        file_operation = self.operation_queue.get()
        if file_operation == 'POISON_PILL':
            self._on_poison_pill()
            return

        assert type(file_operation) in [PathnameOperation,
                                        CreateDirectoriesTask,
                                        DeleteLocalTask,
                                        ResolveDeletionConflictsTask]

        self.logger.debug(u"worker executing: %s", file_operation)
        if __debug__:
            self._worker_pool.track_assign_worker_to_pathname(
                self.ident,
                file_operation.pathname)

        try:
            self.warebox._check_blacklisted_dir()
            if file_operation.is_aborted():
                self.logger.debug(u"Got an already aborted operation, "
                                  "giving up: %s" % file_operation)
            else:
                self.logger.debug(u"Got an operation to handle: %s",
                                  file_operation)
                file_operation.register_abort_handler(self.on_operation_abort)
                self._handle_file_operation(file_operation)

        except Exception:
            self.logger.error(u"Some problem occurred in worker "
                              u"handling operation %r" % file_operation)
            raise

        finally:
            self.logger.debug("Releasing a worker")

            if __debug__:
                self._worker_pool.track_assert_assigned(
                    self.ident, file_operation.pathname)

            self._worker_pool.release_worker()

            if __debug__:
                self._worker_pool.track_release_worker(
                    self.ident,
                    file_operation.pathname)

    def _handle_file_operation(self, file_operation):
        if file_operation.verb == 'UPLOAD':
            self._handle_upload_file_operation(file_operation)
        elif file_operation.verb == 'DOWNLOAD':
            self._handle_download_file_operation(file_operation)
        elif file_operation.verb == 'DELETE_LOCAL':
            self._handle_delete_local_file_operation(file_operation)
        elif file_operation.verb == 'CREATE_DIRECTORIES':
            self._handle_operation_create_directories(file_operation)
        elif file_operation.verb == 'RESOLVE_DELETION_CONFLICTS':
            self._handle_operation_resolve_deletion_conflicts(file_operation)
        else:
            self.logger.warning(u"I should not handle a '%s' operation! "
                                "I'm rejecting it", file_operation.verb)
            file_operation.reject()

    def _send_percentage(self, file_operation, status, percentage):
        now = datetime.now()
        delta = now - self.last_send
        if ((delta.seconds + delta.microseconds/1000000.) > 0.5) \
                or (percentage == 100):
            file_operation.notify_pathname_status_change(
                status, {'percentage': percentage})
            self.last_send = now

    def _handle_network_transfer_operation(self, file_operation):
        '''By locking we mantain the following invariant: if the
        EventQueue tries to abort this operation due to a conflicting
        operation, then EventQueue waits until this operation either
        aborts or completes.
        This preserves the ordering of execution for the conflicting
        operations - that is, the EventQueue doesn't emit
        the conflicting operation while this one is still working.
        '''

        with file_operation.lock:
            if not file_operation.is_aborted():
                self.logger.debug(u"Starting child process to handle file"
                                  " operation: %s" % file_operation)
                try:
                    self._spawn_child(file_operation)
                    self.input_queue.put(('FileOperation', file_operation))
                except Exception as e:
                    self.logger.error(
                        u"Could not spawn a child process: %r" % e)
                    raise OperationRejection(file_operation)
            else:
                self.logger.debug(u"Got an already aborted operation, "
                                  "giving up: %s" % file_operation)
                return False

        if file_operation.verb == 'UPLOAD':
            status = PStatuses.UPLOADING
        else:
            status = PStatuses.DOWNLOADING

        self._send_percentage(file_operation, status, 0)
        termination = False
        max_retry = 3

        while not termination:
            message, content = self.communicationQueue.get()
            self.logger.debug(u'Worker send back %s with content %s'
                              % (message, content))

            if message == 'completed':
                termination = True
                if file_operation.verb == 'DOWNLOAD':
                    return {'actual_etag': content['actual_etag']}
                else:
                    return True

            elif message == 'interrupted':
                self.logger.debug(u"Child has been terminated by "
                                  "Software Operation: %s"
                                  % file_operation)
                file_operation.abort()
                termination = True
                return False

            elif message == 'failed':
                self.logger.error(u"Child has been terminated, "
                                  "Assuming failure for operation: %s"
                                  % file_operation)
                max_retry -= 1
                if max_retry == 0:
                    raise OperationRejection(file_operation)
                self.input_queue.put(('FileOperation', file_operation))

            elif message == 'percentage':
                self._send_percentage(file_operation, status, content)

            elif message == 'log':
                level, msg = content
                self.child_logger[level](msg)

            elif message == 'ShuttingDown':
                self.logger.debug(u"Get a shutting down message from process")
                termination = True
                return False

            elif message == 'DIED':
                self.child = None
                termination = True
                raise OperationRejection(file_operation)

    def _handle_upload_file_operation(self, operation):
        try:
            success = self._handle_network_transfer_operation(operation)
            if success:
                CryptoUtils.clean_env(operation, self.logger)
                self.logger.debug(u"Operation has been completed "
                                  "successfully: %s" % operation)
                self.logger.info(u'Synchronized pathname: %s "%s", which '
                                 'will be persisted after a commit'
                                 % (operation.verb, operation.pathname))
                operation.notify_pathname_status_change(PStatuses.UPLOADED,
                                                        {'percentage': 100})
                operation.complete()

        except Exception as e:
            self.logger.error(u"Error while uploading: %r."
                              " Rejecting the operation: %s" % (e, operation))
            operation.reject()

    def _handle_operation_create_directories(self, task):
        operations = sorted(task.operations, key=lambda op: op.pathname)
        actual_etag = 'd41d8cd98f00b204e9800998ecf8427e'

        for operation in operations:

            # Check integrity
            operation.notify_pathname_status_change(PStatuses.DOWNLOADING)
            res = self._check_download_integrity(operation, actual_etag)
            if not res['valid']:
                # Detected an integrity error. Badly bad.
                self._server_session.signal_download_integrity_error(
                    operation, res['reason'],
                    res['expected_etag'], res['expected_basis'],
                    res['actual_etag'], res['computed_basis'])
                return

            # The directory is valid, create it
            self._make_directories_to(operation.pathname)
            lmtime = self.warebox.get_last_modification_time(operation.pathname)
            operation.lmtime = lmtime
            operation.notify_pathname_status_change(PStatuses.ALIGNED)
            operation.complete()
            self.logger.info(u'Synchronized pathname: %s "%s"'
                             % (operation.verb, operation.pathname))
            self.logger.debug(u"Operation has been completed "
                              "successfully: %s" % operation)

        task.complete()

    def _handle_download_file_operation(self, operation):
        try:
            # Note: it is a normal file, not a directory
            CryptoUtils.set_temp_file(operation, self.cfg)
            success = self._handle_network_transfer_operation(operation)

            if success:

                actual_etag = success['actual_etag']
                res = self._check_download_integrity(operation, actual_etag)
                if not res['valid']:
                    # Detected an integrity error. Badly bad.
                    self._server_session.signal_download_integrity_error(
                        operation, res['reason'],
                        res['expected_etag'], res['expected_basis'],
                        res['actual_etag'], res['computed_basis'])
                    return

                self._make_directories_to(operation.pathname)

                if operation.to_decrypt:
                    # We have not finished yet, leaving the rest to decrypter.
                    # Note: the decrypter duplicates the following ending logic
                    self.cryptoAdapter.put(operation)
                    return

                # It is a valid cleartext file, move it to the warebox
                self.warebox.move(operation.temp_pathname,
                                  operation.pathname,
                                  operation.conflicted)

                self.logger.debug(u"Operation has been completed "
                                  "successfully: %s" % operation)
                self.logger.info(u'Synchronized pathname: %s "%s"'
                                 % (operation.verb, operation.pathname))

                lmtime = self.warebox.get_last_modification_time(operation.pathname)
                operation.lmtime = lmtime
                operation.notify_pathname_status_change(PStatuses.ALIGNED)
                operation.complete()

        except Exception as e:
            self.logger.error(u"Error while downloading: %r."
                              " Rejecting the operation: %s" % (e, operation))
            self.logger.error(u"Stacktrace: %r" % traceback.format_exc())
            operation.reject()

        finally:
            # Just in case the move had failed for any reason
            if not operation.to_decrypt:
                if operation.temp_pathname is not None \
                and os.path.exists(operation.temp_pathname):
                    _try_remove(operation.temp_pathname, self.logger)

    def _make_directories_to(self, pathname):
        """Make sure that the full path for this file exists. It may be
        either a file or a directory.

        There are a couple of reasons why the full path may not exist:
        1) Data has been loaded on the storage with an external tool
           that doesn't explicitly support directories, so they have
           not been created. Treating these directories as something
           to download is wrong: they wouldn't pass the integrity
           check (they really doesn't exist in the trusted dataset),
           so it is better to make them as new local modifications.
        2) The user has deleted while offline a directory that is
           needed by a download. We call it "hierarchy conflict" and
           is uncovered by the diff algorithm, since case 1 would
           still remain unhandled.
        """
        self.warebox.make_directories_to(pathname)

    def _check_download_integrity(self, operation, actual_etag):
        pathname = operation.pathname
        proof = operation.download_info['proof']
        basis = operation.download_info['trusted_basis']

        self.integrity_manager.trusted_basis = basis

        result = {}
        result['valid'] = None
        result['reason'] = None
        result['expected_etag'] = operation.storage_etag
        result['expected_basis'] = basis
        result['actual_etag'] = actual_etag
        result['computed_basis'] = None

        if operation.storage_etag != actual_etag:
            # Note: the etag inside the proof will be
            # checked by the integrity manager.
            self.logger.debug(
                u"Invalid etag of download operation. "
                "Expected etag %s but found %s. %s"
                % (operation.storage_etag, actual_etag, operation))
            result['valid'] = False
            result['reason'] = "Expected etag different from actual etag"
            return result

        try:
            self.integrity_manager.addOperation('DOWNLOAD',
                                                pathname,
                                                proof,
                                                actual_etag)
            result['valid'] = True
            result['computed_basis'] = basis

        except MalformedProofException as e:
            self.logger.debug(u"Invalid proof of download operation: "
                              "%s. %r, %r" % (e, operation, proof))
            self.logger.debug(traceback.format_exc())
            result['valid'] = False
            result['reason'] = "%s" % e

        except WrongBasisFromProofException as e:
            self.logger.debug(u"Integrity check of download operation failed."
                              "Basis %s was expected but the proof computed "
                              "%s. Error details: %s. %r, %r" %
                              (basis, e.operation_basis, e, operation, proof))
            self.logger.debug(traceback.format_exc())
            result['valid'] = False
            result['reason'] = "%s" % e
            result['computed_basis'] = e.operation_basis

        except Exception as e:
            self.logger.debug(u"Integrity check of download operation failed"
                              " with unknown reason: %s. %r, %r"
                              % (e, operation, proof))
            self.logger.debug(traceback.format_exc())
            result['valid'] = False
            result['reason'] = "%s" % e

        finally:
            self.integrity_manager.clear()

        return result

    def _handle_delete_local_file_operation(self, task):
        pathnames = sorted(task.pathname2proof.keys())
        #self.logger.debug("Going to delete pathnames: %s" % pathnames)

        for pathname in pathnames:
            basis = task.trusted_basis
            proof = task.pathname2proof[pathname]
            res = self._check_deletelocal_integrity(pathname, proof, basis)
            if not res['valid']:
                # Detected an integrity error. Badly bad.
                self._server_session.signal_deletelocal_integrity_error(
                    pathname, proof, res['reason'],
                    res['expected_basis'], res['computed_basis'])
                return

        roots = {}
        for pathname in pathnames:
            found_ancestor = False
            for root in roots:
                if pathname.startswith(root):
                    found_ancestor = True
                    break
            if not found_ancestor:
                roots[pathname] = True

        try:
            for pathname in roots.iterkeys():
                self.warebox.delete_tree(pathname)
        except Exception as e:
            self.logger.error(
                u"Caught an operating system exception while "
                u"modifying the filesystem. Are you locking the Warebox? % r"
                % e)
            raise

        task.complete()

    def _check_deletelocal_integrity(self, pathname, proof, trusted_basis):
        self.integrity_manager.trusted_basis = trusted_basis

        result = {}
        result['valid'] = None
        result['reason'] = None
        result['expected_basis'] = trusted_basis
        result['computed_basis'] = None

        try:
            self.integrity_manager.addOperation('DELETE_LOCAL',
                                                pathname,
                                                proof,
                                                None)
            result['valid'] = True
            result['computed_basis'] = trusted_basis

        except MalformedProofException as e:
            self.logger.debug(u"Invalid proof of delete_local operation: "
                              "%s. %s, %s" % (e, pathname, proof.raw))
            self.logger.debug(traceback.format_exc())
            result['valid'] = False
            result['reason'] = "%s" % e

        except WrongBasisFromProofException as e:
            self.logger.debug(u"Integrity check of delete_local operation failed."
                              "Basis %s was expected but the proof computed "
                              "%s. Error details: %s. %r, %r" %
                              (trusted_basis, e.operation_basis, e, pathname, proof.raw))
            self.logger.debug(traceback.format_exc())
            result['valid'] = False
            result['reason'] = "%s" % e
            result['computed_basis'] = e.operation_basis

        except Exception as e:
            self.logger.debug(u"Integrity check of delete_local operation"
                              " failed with unknown reason: %s. %r, %r"
                              % (e, pathname, proof.raw))
            self.logger.debug(traceback.format_exc())
            result['valid'] = False
            result['reason'] = "%s" % e

        finally:
            self.integrity_manager.clear()

        return result

    def _find_new_name(self, pathname):
        # TODO: try harder in finding a name that is available
        curr_time = datetime.now().strftime('%Y-%m-%d %H_%M_%S')
        suffix = ' (Conflicted on %s)' % curr_time
        if pathname.endswith('/'):
            new_pathname = pathname[:-1] + suffix + '/'
        else:
            basename, ext = os.path.splitext(pathname)
            new_pathname = basename + suffix + ext
        return new_pathname

    def _rename_conflicting_pathname(self, pathname, prefix=None):
        new_pathname = self.warebox.rename(pathname, pathname, prefix)
        return new_pathname

    def _handle_operation_resolve_deletion_conflicts(self, task):
        """Solve deletion conflicts by renaming the local file to a new
        pathname. The old pathname will result implicitly deleted.

        Deletion conflicts are tough to resolve. A conflicting pathname:
        a) has been deleted by the server
        b) has an ancestor folder that has been deleted by the server
        c) both
        It must be checked if it's safe leaving the file in its original
        folder (that is, if it still exists).
        """
        conflicts = task.deletion_conflicts
        content_to_delete_locally = task.content_to_delete_locally

        for pathname in conflicts:
            basis = task.trusted_basis
            proof = task.pathname2proof[pathname]
            res = self._check_deletelocal_integrity(pathname, proof, basis)
            if not res['valid']:
                # Detected an integrity error. Badly bad.
                self._server_session.signal_deletelocal_integrity_error(
                    pathname, proof, res['reason'],
                    res['expected_basis'], res['computed_basis'])
                return

        try:
            backupped_folders = {}
            for pathname in conflicts:
                missing_ancestor_folders = filter(lambda p: pathname.startswith(p), content_to_delete_locally)
                # Is it safe leaving the file in its original folder?
                if len(missing_ancestor_folders) > 0:
                    # No, it's been deleted. Backup the whole deleted subtree
                    missing_ancestor_folders = sorted(missing_ancestor_folders)
                    highest_missing_folder = missing_ancestor_folders[0]
                    if not highest_missing_folder in backupped_folders:
                        backup_folder = self._find_new_name(highest_missing_folder)
                        self.warebox.make_directory(backup_folder)
                        backupped_folders[highest_missing_folder] = backup_folder
                    backup_folder = backupped_folders[highest_missing_folder]
                    new_pathname = pathname.replace(highest_missing_folder, backup_folder, 1)
                    self.warebox.make_directories_to(new_pathname)
                    if not self.warebox.is_directory(new_pathname):
                        self.warebox.rename(pathname, new_pathname)
                else:
                    # Yes, just rename the file
                    new_pathname = self._rename_conflicting_pathname(pathname, 'Deleted')
                    self.logger.warning(
                        u"Conflict detected for pathname %r, which has been "
                        u"remotely deleted. Moved the local copy to: %r"
                        % (pathname, new_pathname))

            task.complete()

        except Exception:
            self.logger.error(
                u"Caught an operating system exception while modifying the "
                u"filesystem. Are you locking the Warebox?")
            raise

    def _start_child_logger(self):
        self._stop_child_logger()
        self.child_logs_queue = multiprocessing.Queue()
        self.child_logger = LogsReceiver(self.getName(), self.child_logs_queue)
        self.child_logger.start()
        if self.child_logger is None:
            logger = logging.getLogger(u'FR.WorkerChild of %s' % self.getName())
            self.child_logger = {
                'info': logger.info,
                'debug': logger.debug,
                'warning': logger.warning,
                'error': logger.error,
                'critical': logger.critical
            }

    def _stop_child_logger(self):
        if self.child_logger is not None:
            self.child_logger.stop()
            self.child_logs_queue.put(('log', ('debug', 'Die please!')))
            self.child_logger.join()
            self.child_logger = None

        if self.child_logs_queue is not None:
            self.child_logs_queue.close()
            self.child_logs_queue.join_thread()
            self.child_logs_queue = None

    def _create_multiprocessing_queues(self):
        self._destroy_multiprocessing_queues()
        self.input_queue = Queue.Queue()
        self.communicationQueue = Queue.Queue()

    def _destroy_multiprocessing_queue(self, queue):
        if queue is not None:
            while not queue.empty():
                queue.get_nowait()
#             queue.close()
#             queue.join_thread()
            queue = None

    def _destroy_multiprocessing_queues(self):
        self._destroy_multiprocessing_queue(self.input_queue)
        self._destroy_multiprocessing_queue(self.communicationQueue)

    def _spawn_child(self, file_operation):
        if self.child is None or not self.child.is_alive():
#             self.terminationEvent = multiprocessing.Event()
            self.terminationEvent = threading.Event()
            self._create_multiprocessing_queues()
            self._start_child_logger()
            try:
                self.logger.debug(u"Allocating child process to handle file "
                                  "operation: %s" % file_operation)
                self.child = WorkerChild(self.warebox,
                                         self.input_queue,
                                         self.communicationQueue,
                                         self.terminationEvent,
                                         self._send_percentage,
                                         #self.child_logs_queue,
                                         self.cfg,
                                         self._worker_pool)

                self.child.start()
                self.logger.debug(u"Child process Started to handle file "
                                  "operation: %s" % file_operation)
            except Exception:
                self._stop_child_logger()
                raise

    def on_operation_abort(self, file_operation):
        self.logger.debug(u'Abort detected for the operation I am handling: '
                          '%s. Terminating child process...' % file_operation)
        self.abort_operation()

    def abort_operation(self):
        if self.child is not None and self.child.is_alive():
            try:
                if self.terminationEvent is not None:
                    self.terminationEvent.set()
#                 else:
#                     self.child.terminate()
            except:
                pass

    def _terminate_child(self):
        self.stop_network_transfer()
        if self.child is not None:
            self.input_queue.put(('PoisonPill', None))
            self.child.join(5)
            self.child = None

    def _clean_env(self):
        self._terminate_child()
        self._stop_child_logger()
        self._destroy_multiprocessing_queues()

    def _on_poison_pill(self):
        self.logger.debug(u"Got poison pill.")
        self.must_die.set()
        self._clean_env()

    def terminate(self):
        '''
        Signal the worker that the time has come.
        '''
        self.abort_operation()

    def stop_network_transfer(self):
        self.abort_operation()

    def _termination_requested(self):
        return self.must_die.wait(0.01)