def test_basic_event_log(self):
logger = logging.getLogger(__name__)
filter = tracer.RequestFilter()
logger.addFilter(filter)
with tracer.RequestTracer("12345"):
logger.error("A log record")
def kill(self):
with tracer.RequestTracer(self._request_id):
if self._reply_message_timer:
try:
self._reply_message_timer.cancel()
except Exception as ex:
_g_logger.info("an exception occurred when trying to "
"cancel the timer: " + str(ex))
def shutdown(self):
with tracer.RequestTracer(self._request_id):
try:
if self._reply_message_timer:
self._reply_message_timer.cancel()
self._reply_listener.message_done(self)
except Exception as ex:
_g_logger.warn("Error shutting down the request", ex)
def reply(self, response_document):
"""
Send a reply to this request. This signifies that the user is
done with this object.
"""
with tracer.RequestTracer(self._request_id):
_g_logger.debug("reply() has been called")
self._sm.event_occurred(states.ReplyEvents.USER_REPLIES,
message=response_document)
def nak(self, response_document):
"""
This function is called to out right reject the message. The user
is signifying that this message will not be processed at all.
A call to this function signifies that this object will no longer be
referenced by the user.
"""
with tracer.RequestTracer(self._request_id):
self._sm.event_occurred(states.ReplyEvents.USER_REJECTS_REQUEST,
message=response_document)
def ack(self,
cancel_callback, cancel_callback_args, cancel_callback_kwargs):
"""
Indicate to the messaging system that you have successfully received
this message and stored it for processing.
"""
with tracer.RequestTracer(self._request_id):
self._cancel_callback = cancel_callback
self._cancel_callback_args = cancel_callback_args
if self._cancel_callback_args is None:
self._cancel_callback_args = []
self._cancel_callback_args.insert(0, self)
self._cancel_callback_kwargs = cancel_callback_kwargs
self._sm.event_occurred(states.ReplyEvents.USER_ACCEPTS_REQUEST,
message={})
def run(self):
try:
_g_logger.info("Worker %s thread starting." % self.getName())
done = False
while not done:
try:
workload = self.worker_queue.get()
if workload is None:
continue
if workload.quit:
done = True
self.worker_queue.task_done()
continue
# setup message logging
with tracer.RequestTracer(workload.request_id):
reply_doc = _run_plugin(self._conf, workload.items_map,
workload.request_id,
workload.payload["command"],
workload.payload["arguments"])
self.worker_queue.task_done()
_g_logger.debug(
"Adding the reply document to the reply "
"queue " + str(reply_doc))
work_reply = WorkReply(workload.request_id, reply_doc)
dcm_events.register_callback(self._reply_callback,
args=[work_reply])
_g_logger.info("Reply message sent for command " +
workload.payload["command"])
except queue.Empty:
pass
except:
_g_logger.exception(
"Something went wrong processing the queue")
raise
finally:
_g_logger.info("Worker %s thread ending." % self.getName())
def incoming_message(self, json_doc):
with tracer.RequestTracer(self._request_id):
type_to_event = {
message_types.MessageTypes.ACK:
states.ReplyEvents.REPLY_ACK_RECEIVED,
message_types.MessageTypes.NACK:
states.ReplyEvents.REPLY_NACK_RECEIVED,
message_types.MessageTypes.CANCEL:
states.ReplyEvents.CANCEL_RECEIVED,
message_types.MessageTypes.STATUS:
states.ReplyEvents.STATUS_RECEIVED,
message_types.MessageTypes.REQUEST:
states.ReplyEvents.REQUEST_RECEIVED
}
if 'type' not in json_doc:
raise exceptions.MissingMessageParameterException('type')
if json_doc['type'] not in type_to_event:
raise exceptions.InvalidMessageParameterValueException(
'type', json_doc['type'])
# this next call drives the state machine
self._sm.event_occurred(type_to_event[json_doc['type']],
message=json_doc)
def _process_doc(self, incoming_doc):
if incoming_doc is None:
return
with tracer.RequestTracer(incoming_doc['request_id']):
self._call_reply_observers("incoming_message", incoming_doc)
_g_logger.debug("New message type %s" % incoming_doc['type'])
# if the agent is misbehaving the AM might tell it to kill itself.
# cold.
if incoming_doc["type"] == message_types.MessageTypes.HEMLOCK:
_g_logger.error("HEMLOCK: DCM told me to kill myself.")
os.killpg(0, signal.SIGKILL)
sys.exit(10)
# if it is a alert message short circuit
if incoming_doc["type"] == message_types.MessageTypes.ALERT_ACK:
if self._id_system:
self._id_system.incoming_message(incoming_doc)
return
request_id = incoming_doc["request_id"]
# is this request already in memory?
if request_id in self._requests:
_g_logger.debug("The message was found in the requests.")
# send it through, state machine will deal with it
req = self._requests[request_id]
req.incoming_message(incoming_doc)
return
# if the request id has already been seen by the database
db_record = self._db.lookup_req(request_id)
if db_record:
_g_logger.info("Inflating the record from the DB."
+ request_id)
req = ReplyRPC(
self,
self._conf.agent_id,
self._conn,
request_id,
incoming_doc,
self._db,
timeout=self._timeout,
reply_doc=db_record.reply_doc,
start_state=db_record.state)
# this will probably be used in the near future so get it
# on the memory list
self._requests[request_id] = req
req.incoming_message(incoming_doc)
return
if incoming_doc["type"] == message_types.MessageTypes.REQUEST:
if len(list(self._requests.keys())) >=\
self._conf.messaging_max_at_once > -1:
# short circuit the case where the agent is too busy
dcm_logger.log_to_dcm_console_overloaded(
msg="The new request was rejected because the agent has too many outstanding requests.")
nack_doc = {
'type': message_types.MessageTypes.NACK,
'message_id': utils.new_message_id(),
'request_id': request_id,
'agent_id': self._conf.agent_id,
'error_message': ("The agent can only handle %d "
"commands at once"
% self._conf.messaging_max_at_once)}
self._conn.send(nack_doc)
return
_g_logger.debug("A new request has come in.")
req = ReplyRPC(
self,
self._conf.agent_id,
self._conn,
request_id,
incoming_doc,
self._db,
timeout=self._timeout)
self._call_reply_observers("new_message", req)
# only add the message if processing was successful
self._requests[request_id] = req
try:
self._dispatcher.incoming_request(req)
except Exception:
_g_logger.exception("The dispatcher could not handle a "
"message.")
del self._requests[request_id]
dcm_logger.log_to_dcm_console_messaging_error(
msg="The dispatcher could not handle the message.")
raise
else:
# if we have never heard of the ID and this is not a new
# request we return a courtesy error
_g_logger.debug("Unknown message ID sending a NACK")
nack_doc = {'type': message_types.MessageTypes.NACK,
'message_id': utils.new_message_id(),
'request_id': request_id,
'agent_id': self._conf.agent_id,
'error_message':
"%s is an unknown ID" % request_id}
self._conn.send(nack_doc)
def reply_timeout(self, message_timer):
with tracer.RequestTracer(self._request_id):
_g_logger.debug("reply timeout occurred, resending.")
self._sm.event_occurred(states.RequesterEvents.TIMEOUT,
message_timer=message_timer)