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 _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
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)
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)
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)