Explorar o código

HUE-578: Shell app should have more comprehensive logging for I/O

Aditya Acharya %!s(int64=14) %!d(string=hai) anos
pai
achega
a2b03a1830

+ 33 - 18
apps/shell/src/shell/shellmanager.py

@@ -42,6 +42,8 @@ from eventlet.green import time
 from hadoop.cluster import all_mrclusters, get_all_hdfs
 
 LOG = logging.getLogger(__name__)
+SHELL_OUTPUT_LOGGER = logging.getLogger("shell_output")
+SHELL_INPUT_LOGGER = logging.getLogger("shell_input")
 
 _SETUID_PROG = os.path.join(os.path.dirname(__file__), 'build', 'setuid')
 
@@ -75,7 +77,7 @@ class Shell(object):
     try:
       tty.setraw(parent)
     except tty.error:
-      LOG.debug("Could not set parent fd to raw mode, user will see echoed input.")
+      LOG.debug("Could not set parent fd to raw mode, user will see duplicated input.")
 
     subprocess_env[constants.HOME] = user_info.pw_dir
     command_to_use = [_SETUID_PROG, str(user_info.pw_uid), str(user_info.pw_gid)]
@@ -97,6 +99,12 @@ class Shell(object):
       os.close(child)
       raise
 
+    msg_format =  "%s - shell_id:%s pid:%d - args:%s"
+    msg_args = (username, shell_id, p.pid, ' '.join(command_to_use))
+    msg = msg_format % msg_args
+    SHELL_OUTPUT_LOGGER.info(msg)
+    SHELL_INPUT_LOGGER.info(msg)
+
     # State that shouldn't be touched by any other classes.
     self._output_buffer_length = 0
     self._commands = []
@@ -110,6 +118,7 @@ class Shell(object):
 
     # State that's accessed by other classes.
     self.shell_id = shell_id
+    self.username = username
     # Timestamp that is updated on shell creation and on every output request. Used so that we know
     # when to kill the shell.
     self.time_received = time.time()
@@ -202,13 +211,10 @@ class Shell(object):
 
     Returns a dictionary with {return_code: bool}.
     """
-    LOG.debug("Command received for pid %d : '%s'" % (self.pid, repr(command),))
     # TODO(bc): Track the buffer size to avoid calling getvalue() every time
     if len(self._write_buffer.getvalue()) >= shell.conf.SHELL_WRITE_BUFFER_LIMIT.get():
-      LOG.debug("Write buffer too full, dropping command")
       return { constants.BUFFER_EXCEEDED : True }
     else:
-      LOG.debug("Write buffer has room. Adding command to end of write buffer.")
       self._append_to_write_buffer(command)
       eventlet.spawn_n(self._write_child_when_able)
       return { constants.SUCCESS : True }
@@ -274,8 +280,10 @@ class Shell(object):
       if e.errno == errno.EINTR:
         eventlet.spawn_n(self._write_child_when_able)
       elif e.errno != errno.EAGAIN:
-        format_str = "Encountered error while writing to process with PID %d:%s"
-        LOG.error(format_str % (self.pid, e))
+        error_str = "%s - shell_id:%s pid:%d - Error writing to subprocess:%s" %\
+                                  (self.username, self.shell_id, self.pid, e,)
+        LOG.error(error_str)
+        SHELL_INPUT_LOGGER.error(error_str)
         self.mark_for_cleanup()
     else: # This else clause is on the try/except above, not the if/elif
       if bytes_written != len(buffer_contents):
@@ -320,7 +328,8 @@ class Shell(object):
         pass
       elif e.errno != errno.EAGAIN:
         format_str = "Encountered error while reading from process with PID %d : %s"
-        LOG.error( format_str % (self.subprocess.pid, e))
+        LOG.error(format_str % (self.pid, e))
+        SHELL_OUTPUT_LOGGER.error(format_str % (self.pid, e))
         self.mark_for_cleanup()
     else:
       more_available = length >= shell.conf.SHELL_OS_READ_AMOUNT.get()
@@ -343,12 +352,17 @@ class Shell(object):
       os.close(self._child_fd)
 
       try:
-        LOG.debug("Sending SIGKILL to process with PID %d" % (self.subprocess.pid,))
-        os.kill(self.subprocess.pid, signal.SIGKILL)
-        # We could try figure out which exit statuses are fine and which ones are errors.
-        # But that would be difficult to do correctly since os.wait might block.
+        LOG.debug("Sending SIGKILL to process with PID %d" % (self.pid,))
+        os.kill(self.pid, signal.SIGKILL)
+        _, exitcode = os.waitpid(self.pid, 0)
+        msg = "%s - shell_id:%s pid:%d - Exited with status %d" % (self.username, self.shell_id, self.pid, exitcode)
       except OSError:
-        pass # This means the subprocess was already killed, which happens if the command was "quit"
+        msg = "%s - shell_id:%s pid:%d - Killed successfully" % (self.username, self.shell_id, self.pid,)
+        # This means the subprocess was already killed, which happens if the command was "quit"
+        # This can also happen if the waitpid call results in an error, which we don't care about.
+      LOG.info(msg)
+      SHELL_OUTPUT_LOGGER.info(msg)
+      SHELL_INPUT_LOGGER.info(msg)
     finally:
       self.destroyed = True
 
@@ -495,16 +509,17 @@ class ShellManager(object):
     user_metadata = self._meta[username]
     shell_id = user_metadata.get_next_id()
     try:
-      LOG.debug("Trying to create a %s shell for user %s" % (shell_name, username))
+      msg = "%s - shell_id:%s - Creating %s shell with command '%s'" % (username, shell_id, shell_name, repr(command))
+      LOG.debug(msg)
       # Let's make a copy of the subprocess's environment since the Shell constructor will modify
       # the dictionary we pass in.
       subprocess_env = self._env_by_short_name.get(shell_name, {}).copy()
       shell_instance = Shell(command, subprocess_env, shell_id, username, self._delegation_token_dir)
     except (OSError, ValueError, KeyError, MergeToolException):
-      LOG.exception("Could not create %s shell for '%s'" % (shell_name, username))
+      LOG.exception("%s - shell_id:%s - Could not create %s shell" % (username, shell_id, shell_name))
       return { constants.SHELL_CREATE_FAILED : True }
 
-    LOG.debug("Shell successfully created")
+    LOG.debug("%s - shell_id:%s pid:%d - Shell successfully created" % (username, shell_id, shell_instance.pid))
     user_metadata.increment_count()
     self._shells[(username, shell_id)] = shell_instance
     self._shells_by_fds[shell_instance._fd] = shell_instance
@@ -516,10 +531,10 @@ class ShellManager(object):
     """
     shell_instance = self._shells.get((username, shell_id))
     if not shell_instance:
-      response = "User '%s' has no shell with ID '%s'" % (username, shell_id)
+      response = "%s - shell_id:%s - No such shell exists" % (username, shell_id)
     else:
       shell_instance.mark_for_cleanup()
-      response = "Shell successfully killed"
+      response = "%s - shell_id:%s - Shell successfully marked for cleanup" % (username, shell_id)
     LOG.debug(response)
     return response
 
@@ -707,7 +722,7 @@ class ShellManager(object):
         if cached_output:
           result[shell_id] = cached_output
       else:
-        LOG.warn("User '%s' has no shell with ID '%s'" % (username, shell_id))
+        LOG.warn("%s - shell_id:%s - No such shell exists" % (username, shell_id))
         result[shell_id] = { constants.NO_SHELL_EXISTS: True }
 
     return result

+ 24 - 0
apps/shell/src/shell/views.py

@@ -17,6 +17,7 @@
 
 from desktop.lib.django_util import render
 from django.http import HttpResponse
+import logging
 import simplejson
 import shell.conf
 import shell.constants as constants
@@ -24,6 +25,9 @@ import shell.utils as utils
 from shell.shellmanager import ShellManager
 import sys
 
+SHELL_OUTPUT_LOGGER = logging.getLogger("shell_output")
+SHELL_INPUT_LOGGER = logging.getLogger("shell_input")
+
 def _running_with_spawning(request):
   return 'eventlet.input' in request.META
 
@@ -49,6 +53,8 @@ def create(request):
     key_name = request.POST.get(constants.KEY_NAME, "")
   else:
     key_name = request.GET.get(constants.KEY_NAME, "")
+  SHELL_INPUT_LOGGER.info("%s %s - Create '%s' shell" %
+                (request.META.get('REMOTE_ADDR'), user.username, key_name))
   result = shell_manager.try_create(user, key_name)
   if request.method == "POST":
     return HttpResponse(simplejson.dumps(result), mimetype="application/json")
@@ -68,6 +74,8 @@ def kill_shell(request):
   shell_manager = ShellManager.global_instance()
   username = request.user.username
   shell_id = request.POST[constants.SHELL_ID]
+  SHELL_INPUT_LOGGER.info("%s %s - shell_id:%s - Kill shell" %
+                 (request.META.get('REMOTE_ADDR'), username, shell_id))
   result = shell_manager.kill_shell(username, shell_id)
   return HttpResponse(result)
 
@@ -78,7 +86,15 @@ def restore_shell(request):
   shell_manager = ShellManager.global_instance()
   username = request.user.username
   shell_id = request.POST[constants.SHELL_ID]
+  SHELL_OUTPUT_LOGGER.info("%s %s - shell_id:%s - Attempting restore" %
+                      (request.META.get('REMOTE_ADDR'), username, shell_id))
   result = shell_manager.get_previous_output(username, shell_id)
+  log_output = {}
+  if constants.OUTPUT in result:
+    log_output[constants.OUTPUT] = result[constants.OUTPUT]
+  log_output = repr(log_output)
+  SHELL_OUTPUT_LOGGER.info("%s %s - shell_id:%s - Restore output: '%s'" %
+              (request.META.get('REMOTE_ADDR'), username, shell_id, log_output ))
   return HttpResponse(simplejson.dumps(result), mimetype="application/json")
 
 def process_command(request):
@@ -89,6 +105,8 @@ def process_command(request):
   username = request.user.username
   shell_id = request.POST[constants.SHELL_ID]
   command = request.POST.get(constants.COMMAND, "")
+  SHELL_INPUT_LOGGER.info("%s %s - shell_id:%s - Command:'%s'" %
+              (request.META.get('REMOTE_ADDR'), username, shell_id, command))
   result = shell_manager.process_command(username, shell_id, command)
   return HttpResponse(simplejson.dumps(result), mimetype="application/json")
 
@@ -104,6 +122,12 @@ def retrieve_output(request):
   except ValueError:
     shell_pairs = []
   result = shell_manager.retrieve_output(username, hue_instance_id, shell_pairs)
+  for key, value in result.iteritems():
+    if isinstance(value, dict) and constants.OUTPUT in value:
+      log_format = '%s %s - shell_id:%s - Output: "%s"'
+      log_args = (request.META.get('REMOTE_ADDR'), username, key,
+                                        repr(value[constants.OUTPUT]))
+      SHELL_OUTPUT_LOGGER.info(log_format % log_args)
   return HttpResponse(simplejson.dumps(result), mimetype="application/json")
 
 def add_to_output(request):

+ 22 - 2
desktop/conf.dist/log.conf

@@ -22,6 +22,14 @@ handlers=logfile,errorlog
 handlers=accesslog
 qualname=access
 
+[logger_shell_output]
+handlers=shell_output_log
+qualname=shell_output
+
+[logger_shell_input]
+handlers=shell_input_log
+qualname=shell_input
+
 # The logrotation limit is set at 5MB per file for a total of 5 copies.
 # I.e. 25MB for each set of logs.
 [handler_accesslog]
@@ -38,6 +46,18 @@ level=ERROR
 formatter=default
 args=('%LOG_DIR%/error.log', 'a', 5000000, 5)
 
+[handler_shell_output_log]
+class=handlers.RotatingFileHandler
+level=INFO
+formatter=default
+args=('%LOG_DIR%/shell_output.log', 'a', 5000000, 5)
+
+[handler_shell_input_log]
+class=handlers.RotatingFileHandler
+level=INFO
+formatter=default
+args=('%LOG_DIR%/shell_input.log', 'a', 5000000, 5)
+
 [formatter_default]
 format=[%(asctime)s] %(module)-12s %(levelname)-8s %(message)s
 datefmt=%d/%b/%Y %H:%M:%S +0000
@@ -47,10 +67,10 @@ format=[%(asctime)s] %(levelname)-8s %(message)s
 datefmt=%d/%b/%Y %H:%M:%S +0000
 
 [loggers]
-keys=root,access
+keys=root,access,shell_output,shell_input
 
 [handlers]
-keys=logfile,accesslog,errorlog
+keys=logfile,accesslog,errorlog,shell_output_log,shell_input_log
 
 [formatters]
 keys=default,access

+ 22 - 2
desktop/conf/log.conf

@@ -17,6 +17,14 @@ handlers=logfile,errorlog
 handlers=accesslog
 qualname=access
 
+[logger_shell_output]
+handlers=shell_output_log
+qualname=shell_output
+
+[logger_shell_input]
+handlers=shell_input_log
+qualname=shell_input
+
 [handler_stderr]
 class=StreamHandler
 formatter=default
@@ -43,6 +51,18 @@ level=DEBUG
 formatter=default
 args=('%LOG_DIR%/%PROC_NAME%.log', 'a', 1000000, 3)
 
+[handler_shell_output_log]
+class=handlers.RotatingFileHandler
+level=DEBUG
+formatter=default
+args=('%LOG_DIR%/shell_output.log', 'a', 1000000, 3)
+
+[handler_shell_input_log]
+class=handlers.RotatingFileHandler
+level=DEBUG
+formatter=default
+args=('%LOG_DIR%/shell_input.log', 'a', 1000000, 3)
+
 [formatter_default]
 format=[%(asctime)s] %(module)-12s %(levelname)-8s %(message)s
 datefmt=%d/%b/%Y %H:%M:%S +0000
@@ -57,10 +77,10 @@ datefmt=%d/%b/%Y %H:%M:%S +0000
 ########################################
 
 [loggers]
-keys=root,access
+keys=root,access,shell_output,shell_input
 
 [handlers]
-keys=stderr,logfile,accesslog,errorlog
+keys=stderr,logfile,accesslog,errorlog,shell_output_log,shell_input_log
 
 [formatters]
 keys=default,access