def __log_about_double_return(self, frame, body):
if not self.__have_warned_about_double_unroutable_already:
body_json = json.loads(body)
logerror(LOGGER, 'The RabbitMQ node refused a message a second time (with the original routing key "%s" and the emergency routing key "%s"). Dropping the message.',
body_json['original_routing_key'], frame.routing_key)
self.__have_warned_about_double_unroutable_already = True
logdebug(LOGGER, 'This is the second time the message comes back. Dropping it.')
def __wait_some_more_and_redecide(self, iteration):
wait_seconds = defaults.RABBIT_ASYN_FINISH_WAIT_SECONDS
logdebug(
LOGGER,
'Gentle finish (iteration %i): Waiting some more for pending messages...',
self.__close_decision_iterations)
# Instead of time.sleep(), add an event to the thread's ioloop
self.__close_decision_iterations += 1
if self.thread._connection is not None:
self.thread._connection.add_timeout(
wait_seconds, self.recursive_decision_about_closing)
self.__is_in_process_of_gently_closing = True
# Problem: If a reconnect occurs after this, this event will be lost.
# I cannot retrieve if from the ioloop and pass it to the new one.
# So, during a reconnection, we check if gently-finish was running,
# and add a new timeout to the new ioloop, using
# "continue_gently_closing_if_applicable()".
# This may mess up the amount of time the gently-finish takes, though.
# TODO Maybe one day it is possible to transfer events from one ioloop to
# another?
else:
logerror(
LOGGER,
'Connection was None when trying to wait for pending messages. Synchronization error between threads!'
)
def __wait_for_thread_to_finish_gently(self):
# This is executed by the main thread and thus should be placed in the
# main thread's method, but it is so important not to forget to wait,
# that it is better to have it boung to the thread's method "add_event_gently_finish()"
logdebug(LOGGER, 'Now waiting for gentle close-down of RabbitMQ connection...')
self.__gently_finish_ready.wait()
logdebug(LOGGER, 'Finished waiting for gentle close-down of RabbitMQ connection.')
def __force_finish(self, msg):
logdebug(LOGGER, 'Force finishing, reason: %s.', msg)
self.statemachine.set_to_force_finished()
reply_code = self.thread.ERROR_CODE_CONNECTION_CLOSED_BY_USER
reply_text = msg+' '+self.thread.ERROR_TEXT_CONNECTION_FORCE_CLOSED
self.__close_down(reply_code, reply_text)
self.__inform_about_state_at_shutdown()
def __close_because_no_point_in_waiting(self):
# Logging, depending on why we closed...
logdebug(
LOGGER,
'Gentle finish (iteration %i): Closing, as there is no point in waiting any longer.',
self.__close_decision_iterations)
if self.statemachine.get_detail_closed_by_publisher():
logwarn(
LOGGER,
'Not waiting for pending messages: No connection to server (previously closed by user).'
)
elif self.statemachine.detail_could_not_connect:
logwarn(
LOGGER,
'Not waiting for pending messages: No connection to server (unable to connect).'
)
else:
logwarn(
LOGGER,
'Not waiting for pending messages: No connection to server (unsure why).'
)
# Actual close
self.__force_finish(
'Force finish as we are not sending the messages anyway.')
self.__tell_publisher_to_stop_waiting_for_gentle_finish()
def set_next_host(self):
if len(self.__trusted_nodes) > 0:
self.__current_node = self.__get_highest_priority_node(
self.__trusted_nodes)
logdebug(LOGGER, 'Selected a trusted node: %s',
self.__current_node['host'])
elif len(self.__open_nodes) > 0:
self.__current_node = self.__get_highest_priority_node(
self.__open_nodes)
logdebug(LOGGER, 'Selected an open node: %s',
self.__current_node['host'])
else:
if self.__current_node is None:
logwarn(
LOGGER,
'Unexpected: No RabbitMQ node left to try, and there is no current one.'
)
raise esgfpid.exceptions.ArgumentError(
'No RabbitMQ nodes were passed at all.')
logwarn(LOGGER,
'No RabbitMQ node left to try! Leaving the last one: %s',
self.__current_node['host'])
self.__exchange_name = self.__current_node['exchange_name']
def __add_file(self, **args):
logdebug(LOGGER, 'Adding file "%s" with handle "%s".', args['file_name'], args['file_handle'])
self.__add_file_to_datasets_children(args['file_handle'])
self.__adapt_file_args(args)
self.__create_and_store_file_publication_message(args)
self.__set_machine_state_to_files_added()
logtrace(LOGGER, 'Adding file done.')
def __log_receival_one_message(self, message):
if self.__first_message_receival:
logdebug(LOGGER, 'Handing over first message to rabbit thread...')
self.__first_message_receival = False
logtrace(LOGGER, 'Handing over one message over to the rabbit thread (%s)', message)
log_every_x_times(LOGGER, self.__logcounter_received, self.__LOGFREQUENCY, 'Handing over one message over to the rabbit thread (no. %i).', self.__logcounter_received)
self.__logcounter_received += 1
def __init__(self, node_manager):
logdebug(LOGGER, 'Initializing rabbit connector...')
'''
To check whether the thread has been started yet.
If not, the methods of this module will raise an error, to
make sure that the library caller will start the thread.
'''
self.__not_started_yet = True
# To be filled after join:
self.__leftovers_unpublished = [] # will be filled after join
self.__leftovers_unconfirmed = [] # will be filled after join
self.__leftovers_nacked = [] # will be filled after join
# Shared objects
self.__statemachine = StateMachine()
self.__unpublished_messages_queue = Queue.Queue()
# Log flags
self.__first_message_receival = True
self.__logcounter_received = 1
self.__LOGFREQUENCY = 10
# Actually created the thread:
#self.__thread = RabbitThread(self.__statemachine, self.__unpublished_messages_queue, self, node_manager)
self.__thread = self.__create_thread(node_manager)
logdebug(LOGGER, 'Initializing rabbit connector... done.')
def __add_emergency_routing_key(self, body_json):
emergency_routing_key = esgfpid.utils.RABBIT_EMERGENCY_ROUTING_KEY
key_for_routing_key = esgfpid.assistant.messages.JSON_KEY_ROUTING_KEY
# If there was no routing key, set the original one to 'None'
if key_for_routing_key not in body_json:
logerror(
LOGGER,
'Very unexpected: RabbitMQ returned a message that had no routing key: %s',
body_json)
body_json[key_for_routing_key] = 'None'
# If it already HAS the emergency routing key, do not adapt the routing key
# (This means the message already came back a second time...)
if body_json[key_for_routing_key] == emergency_routing_key:
pass
# Otherwise, store the original one in another field...
# and overwrite it by the emergency routing key:
else:
body_json['original_routing_key'] = body_json[key_for_routing_key]
logdebug(LOGGER, 'Adding emergency routing key %s',
emergency_routing_key)
body_json[key_for_routing_key] = emergency_routing_key
return body_json
def __init__(self, **args):
logdebug(LOGGER, 'Constructor for Publication assistant for dataset "%s", version "%s" at host "%s".',
args['drs_id'],
args['version_number'],
args['data_node']
)
# Check args
mandatory_args = ['drs_id', 'version_number', 'data_node', 'prefix',
'thredds_service_path', 'is_replica', 'coupler',
'consumer_solr_url']
optional_args = []
utils.check_presence_of_mandatory_args(args, mandatory_args)
utils.add_missing_optional_args_with_value_none(args, optional_args)
self.__enforce_integer_version_number(args)
self.__enforce_boolean_replica_flag(args)
# Init methods...
self.__store_args_in_attributes(args)
self.__define_other_attributes()
self.__create_and_store_dataset_handle()
self.__init_state_machine()
logdebug(LOGGER, 'Done: Constructor for Publication assistant for dataset "%s", version "%i" at host "%s".',
args['drs_id'],
args['version_number'],
args['data_node']
)
def on_connection_error(self, connection, msg):
oldhost = self.__get_whole_host_name()
time_passed = datetime.datetime.now() - self.__start_connect_time
time_passed_seconds = time_passed.total_seconds()
logerror(
LOGGER,
'Could not connect to %s: "%s" (connection failure after %s seconds)',
oldhost, msg, time_passed_seconds)
self.__store_connection_error_info(msg, oldhost)
# If there was a force-finish, we do not reconnect.
if self.statemachine.is_FORCE_FINISHED():
errormsg = 'Permanently failed to connect to RabbitMQ.'
if self.statemachine.detail_asked_to_gently_close_by_publisher:
errormsg += ' Tried all hosts until was force-closed by user.'
elif self.statemachine.detail_asked_to_force_close_by_publisher:
errormsg += ' Tried all hosts until a user close-down forced us to give up (e.g. the maximum waiting time was reached).'
errormsg += ' Giving up. No PID requests will be sent.'
self.__give_up_reconnecting_and_raise_exception(errormsg)
# If there is alternative URLs, try one of them:
if self.__node_manager.has_more_urls():
logdebug(LOGGER,
'Connection failure: %s fallback URLs left to try.',
self.__node_manager.get_num_left_urls())
self.__node_manager.set_next_host()
newhost = self.__get_whole_host_name()
loginfo(LOGGER,
'Connection failure: Trying to connect (now) to %s.',
newhost)
reopen_seconds = 0
self.__wait_and_trigger_reconnection(connection, reopen_seconds)
# If there is no URLs, reset the node manager to
# start at the first nodes again...
else:
self.__reconnect_counter += 1
if self.__reconnect_counter <= self.__max_reconnection_tries:
reopen_seconds = self.__wait_seconds_before_reconnect
logdebug(
LOGGER,
'Connection failure: Failed connecting to all hosts. Waiting %s seconds and starting over.',
reopen_seconds)
self.__node_manager.reset_nodes()
newhost = self.__node_manager.get_connection_parameters().host
loginfo(
LOGGER,
'Connection failure: Trying to connect (in %s seconds) to %s.',
reopen_seconds, newhost)
self.__wait_and_trigger_reconnection(connection,
reopen_seconds)
# Give up after so many tries...
else:
errormsg = (
'Permanently failed to connect to RabbitMQ. Tried all hosts %s times. Giving up. No PID requests will be sent.'
% (self.__max_reconnection_tries + 1))
self.__give_up_reconnecting_and_raise_exception(errormsg)
def __reset_reconnect_counter(self):
logdebug(
LOGGER,
'Resetting reconnection counter, because a channel was successfully opened.'
)
self.__backup_reconnect_counter = self.__reconnect_counter # we may need to undo this later...
self.__reconnect_counter = 0
def make_data_cart_pid(self, dict_of_drs_ids_and_pids):
logdebug(LOGGER, 'Making a PID for a data cart full of datasets...')
# Check arg
if not type(dict_of_drs_ids_and_pids) == type(dict()):
if type(dict_of_drs_ids_and_pids) == type([]):
raise esgfpid.exceptions.ArgumentError(
'Please provide a dictionary of dataset ids and handles, not a list'
)
else:
raise esgfpid.exceptions.ArgumentError(
'Please provide a dictionary of dataset ids and handles')
# Make a pid (hash on the content):
cart_handle = DataCartAssistant._get_handle_string_for_datacart(
dict_of_drs_ids_and_pids, self.__prefix)
# Make and send message
message = self.__make_message(cart_handle, dict_of_drs_ids_and_pids)
self.__send_message_to_queue(message)
# Return pid
logdebug(LOGGER,
'Making a PID for a data cart full of datasets... done.')
loginfo(LOGGER, 'Requesting to create PID for data cart (%s).',
cart_handle)
return cart_handle
def __send_a_message(self, message):
if self.__statemachine.is_WAITING_TO_BE_AVAILABLE():
self.__log_receival_one_message(message)
self.__put_one_message_into_queue_of_unsent_messages(message)
elif self.__statemachine.is_AVAILABLE():
self.__log_receival_one_message(message)
self.__put_one_message_into_queue_of_unsent_messages(message)
self.__trigger_one_publish_action()
elif self.__statemachine.is_AVAILABLE_BUT_WANTS_TO_STOP(
) or self.__statemachine.is_PERMANENTLY_UNAVAILABLE():
errormsg = 'Accepting no more messages'
logdebug(LOGGER, errormsg + ' (dropping %s).', message)
logwarn(
LOGGER,
'RabbitMQ module was closed and does not accept any more messages. Dropping message. Reason: %s',
self.__statemachine.get_reason_shutdown())
# Note: This may happen if the connection failed. We may not stop
# the publisher in this case, so we do not raise an exception.
# We only raise an exception if the closing was asked by the publisher!
if self.__statemachine.get_detail_closed_by_publisher():
raise OperationNotAllowed(errormsg)
elif self.__statemachine.is_NOT_STARTED_YET():
errormsg(
'Cannot send a message, the messaging thread was not started yet!'
)
logwarn(LOGGER, errormsg + ' (dropping %s).', message)
raise OperationNotAllowed(errormsg)
def add_trusted_node(self, **kwargs):
kwargs['is_open'] = False
node_info = self.__add_node(self.__trusted_nodes,
self.__trusted_nodes_archive, **kwargs)
self.__has_trusted = True
logdebug(LOGGER, 'Trusted rabbit: %s',
self.__get_node_log_string(node_info))
def get_routing_key_and_string_message_from_message_if_possible(msg):
# Try to convert message to json:
json_ok = False
msg_json = None
msg_string = None
if msg is None:
raise ValueError('The message that was passed is None.')
# Get JSON from message, if possible!
if isinstance(msg, basestring):
try:
# Valid string message --> JSON
msg_string = msg
msg_json = json.loads(msg)
json_ok = True
logdebug(LOGGER, 'Message was transformed to json.')
except ValueError as e:
# Invalid string message
loginfo(LOGGER, 'Message seems to be invalid json: %s', msg)
msg_string = str(msg)
json_ok = False
else:
try:
# Message is json already.
msg_string = json.dumps(msg)
msg_json = msg
json_ok = True
logtrace(LOGGER, 'Message was already json.')
except TypeError as e:
if 'not JSON serializable' in e.message:
# Message was whatever.
msg_string = str(msg)
json_ok = False
msg = (
'Message was neither JSON nor string and not understandable: %s'
% msg_string)
loginfo(LOGGER, msg)
raise ValueError(msg)
# If we succeeded, try to get routing key:
routing_key = None
if json_ok:
try:
routing_key = msg_json['ROUTING_KEY']
logtrace(LOGGER, 'Routing key extracted from message.')
except (KeyError, TypeError) as e:
logdebug(LOGGER, 'No routing key in message.')
routing_key = esgfpid.defaults.RABBIT_DEFAULT_ROUTING_KEY
pass # There is no routing key in the message
else:
routing_key = esgfpid.defaults.RABBIT_DEFAULT_ROUTING_KEY
return routing_key, msg_string
def __close_because_all_done(self, iteration):
logdebug(
LOGGER,
'Gentle finish (iteration %i): All messages sent and confirmed in %ith try (waited and rechecked %i times).',
self.__close_decision_iterations, iteration, iteration - 1)
loginfo(LOGGER, 'All messages sent and confirmed. Closing.')
self.__normal_finish()
self.__tell_publisher_to_stop_waiting_for_gentle_finish()
def __log_previously_stored_files_found(self):
concat_files = ', '.join(self.__list_of_previous_files)
type_files = type(self.__list_of_previous_files)
logdebug(LOGGER, 'Previously published fileset: %s (%s)', concat_files,
type_files)
loginfo(
LOGGER,
'Data integrity check will be run after files were specified.')
def __log_receival_many_messages(self, messages):
if self.__first_message_receival:
logdebug(LOGGER, 'Handing over first message to rabbit thread...')
self.__first_message_receival = False
logdebug(LOGGER,
'Batch sending: Handing %i messages over to the sender.',
len(messages))
self.__logcounter_received += len(messages)
def __remove_delivery_tag_and_message_single(self, deliv_tag):
try:
self.__unconfirmed_delivery_tags.remove(deliv_tag)
ms = self.__unconfirmed_messages_dict.pop(str(deliv_tag))
logtrace(LOGGER, 'Received ack for message %s.', ms)
except ValueError as e:
logdebug(LOGGER, 'Could not remove %i from unconfirmed.',
deliv_tag)
def __react_on_single_delivery_ack(self, deliv_tag):
self.__remove_delivery_tag_and_message_single(deliv_tag)
logdebug(LOGGER,
'Received ack for delivery tag %i. Waiting for %i confirms.',
deliv_tag, len(self.__unconfirmed_delivery_tags))
logtrace(LOGGER, 'Received ack for delivery tag %i.', deliv_tag)
logtrace(LOGGER, 'Now left in queue to be confirmed: %i messages.',
len(self.__unconfirmed_delivery_tags))
def __resend_message(self, returned_frame, props, body):
try:
body_json = json.loads(body)
body_json = self.__add_emergency_routing_key(body_json)
self.__resend_an_unroutable_message(json.dumps(body_json))
except pika.exceptions.ChannelClosed as e:
logdebug(LOGGER, 'Error during "on_message_not_accepted": %s: %s', e.__class__.__name__, e.message)
logerror(LOGGER, 'Could not resend message: %s: %s', e.__class__.__name__, e.message)
def recursive_decision_about_closing(self):
logdebug(LOGGER, 'Gentle finish (iteration %i): Deciding about whether we can close the thread or not...', self.__close_decision_iterations)
iteration = self.__close_decision_iterations
if self.__are_any_messages_pending():
self.__inform_about_pending_messages()
self.__decide_what_to_do_about_pending_messages(iteration)
else:
self.__close_because_all_done(iteration)
def continue_gently_closing_if_applicable(self):
if self.__is_in_process_of_gently_closing:
logdebug(LOGGER, 'Continue gentle shutdown even after reconnect (iteration %i)...', self.__close_decision_iterations)
if self.thread._connection is not None:
wait_seconds = defaults.RABBIT_ASYN_FINISH_WAIT_SECONDS
self.thread._connection.add_timeout(wait_seconds, self.recursive_decision_about_closing)
else:
logerror(LOGGER, 'Connection was None when trying to wait for pending messages (after reconnect). Synchronization error between threads!')
def __module_is_not_progressing_anymore(self):
if self.statemachine.is_PERMANENTLY_UNAVAILABLE(
) or self.statemachine.is_FORCE_FINISHED():
logdebug(
LOGGER,
'Gentle finish (iteration %i): The rabbit thread is not active anymore, so we might as well close it.',
self.__close_decision_iterations)
return True
return False
def __make_ready_for_publishing(self):
logdebug(
LOGGER,
'(Re)connection established, making ready for publication...')
# Check for unexpected errors:
if self.thread._channel is None:
logerror(
LOGGER,
'Channel is None after connecting to server. This should not happen.'
)
self.statemachine.set_to_permanently_unavailable()
if self.thread._connection is None:
logerror(
LOGGER,
'Connection is None after connecting to server. This should not happen.'
)
self.statemachine.set_to_permanently_unavailable()
# Normally, it should already be waiting to be available:
if self.statemachine.is_WAITING_TO_BE_AVAILABLE():
logdebug(LOGGER, 'Setup is finished. Publishing may start.')
logtrace(LOGGER, 'Publishing will use channel no. %s!',
self.thread._channel.channel_number)
self.statemachine.set_to_available()
self.__check_for_already_arrived_messages_and_publish_them()
# It was asked to close in the meantime (but might be able to publish the last messages):
elif self.statemachine.is_AVAILABLE_BUT_WANTS_TO_STOP():
logdebug(
LOGGER,
'Setup is finished, but the module was already asked to be closed in the meantime.'
)
self.__check_for_already_arrived_messages_and_publish_them()
# It was force-closed in the meantime:
elif self.statemachine.is_PERMANENTLY_UNAVAILABLE(
): # state was set in shutter module's __close_down()
if self.statemachine.get_detail_closed_by_publisher():
logdebug(
LOGGER,
'Setup is finished now, but the module was already force-closed in the meantime.'
)
self.shutter.safety_finish(
'closed before connection was ready. reclosing.')
elif self.statemachine.detail_could_not_connect:
logerror(
LOGGER,
'This is not supposed to happen. If the connection failed, this part of the code should not be reached.'
)
else:
logerror(
LOGGER,
'This is not supposed to happen. An unknown event set this module to be unavailable. When was this set to unavailable?'
)
else:
logdebug(LOGGER, 'Unexpected state.')
def __rescue_unconfirmed_messages(self):
if self.__thread.is_alive():
logwarn(LOGGER, 'Cannot retrieve unconfirmed messages while thread still alive.')
else:
self.__leftovers_unconfirmed = self.__get_unconfirmed_messages_as_list()
num = len(self.__leftovers_unconfirmed)
if num > 0:
logdebug(LOGGER, 'Rescued %i unconfirmed messages.', num)
else:
logdebug(LOGGER, 'No unconfirmed messages to rescue.')
def __rescue_nacked_messages(self):
if self.__thread.is_alive():
logwarn(LOGGER, 'Cannot retrieve rejected (NACKed) messages while thread still alive.')
else:
self.__leftovers_nacked = self.__get_nacked_messages_as_list()
num = len(self.__leftovers_nacked)
if num > 0:
logdebug(LOGGER, 'Rescued %i rejected (NACKed) messages.', num)
else:
logdebug(LOGGER, 'No rejected (NACKed) messages to rescue.')
def __log_publication_trigger(self):
if self.__first_publication_trigger:
logdebug(
LOGGER,
'Received first trigger for publishing message to RabbitMQ.')
self.__first_publication_trigger = False
logtrace(
LOGGER,
'Received trigger for publishing message to RabbitMQ, and module is ready to accept it.'
)