Fix NIMBY lock and refactor Nimby to Factory (#1106)

* Fix NIMBY lock and refactor Nimby to Factory

Nimby now has two modes, Select and Pynput. Windows
hosts will activate the Pynput mode by default.
Bug fix: Two changes in rqcore.py: start() under
isDesktop to call onNimbyLock() if nimby override
is true. Second in launchFrame, added another condition
if Nimby override is True and user is active to not
launch frame. Revamped logging, removed print
statements.

* Fix Pylint errors

* Adding logging for pyput import failures

rqd/rqd/__main__.py

@@ -61,15 +61,13 @@
 
 def setupLogging():
     """Sets up the logging for RQD.
+       Logs to /var/log/messages"""
 
-    Logs to /var/log/messages"""
-    # TODO(bcipriano) These should be config based. (Issue #72)
-    consoleFormat = '%(asctime)s %(levelname)-9s rqd3-%(module)-10s %(message)s'
-    consoleLevel = logging.DEBUG
-    fileFormat = '%(asctime)s %(levelname)-9s rqd3-%(module)-10s %(message)s'
-    fileLevel = logging.WARNING  # Equal to or greater than the consoleLevel
+    consolehandler = logging.StreamHandler()
+    consolehandler.setLevel(rqd.rqconstants.CONSOLE_LOG_LEVEL)
+    consolehandler.setFormatter(logging.Formatter(rqd.rqconstants.LOG_FORMAT))
+    logging.getLogger('').addHandler(consolehandler)
 
-    logging.basicConfig(level=consoleLevel, format=consoleFormat)
     if platform.system() in ('Linux', 'Darwin'):
         if platform.system() == 'Linux':
             syslogAddress = '/dev/log'
@@ -83,9 +81,10 @@ def setupLogging():
         logfile = logging.FileHandler(os.path.expandvars('%TEMP%/openrqd.log'))
     else:
         logfile = logging.handlers.SysLogHandler()
-    logfile.setLevel(fileLevel)
-    logfile.setFormatter(logging.Formatter(fileFormat))
+    logfile.setLevel(rqd.rqconstants.FILE_LOG_LEVEL)
+    logfile.setFormatter(logging.Formatter(rqd.rqconstants.LOG_FORMAT))
     logging.getLogger('').addHandler(logfile)
+    logging.getLogger('').setLevel(logging.DEBUG)
 
 
 def usage():

rqd/rqd/cuerqd.py

@@ -60,13 +60,13 @@ def getRunningFrame(self, frameId):
 
     def nimbyOff(self):
         """Disables Nimby on the host."""
-        print(self.rqdHost, "Turning off Nimby")
+        log.info(self.rqdHost, "Turning off Nimby")
         log.info("rqd nimbyoff by %s", os.environ.get("USER"))
         self.stub.NimbyOff(rqd.compiled_proto.rqd_pb2.RqdStaticNimbyOffRequest())
 
     def nimbyOn(self):
         """Enables Nimby on the host."""
-        print(self.rqdHost, "Turning on Nimby")
+        log.info(self.rqdHost, "Turning on Nimby")
         log.info("rqd nimbyon by %s", os.environ.get("USER"))
         self.stub.NimbyOn(rqd.compiled_proto.rqd_pb2.RqdStaticNimbyOnRequest())
 

rqd/rqd/rqconstants.py

@@ -116,10 +116,15 @@
 OVERRIDE_PROCS = None # number of physical cpus. ex: None or 2
 OVERRIDE_MEMORY = None # in Kb
 OVERRIDE_NIMBY = None # True to turn on, False to turn off
+USE_NIMBY_PYNPUT = platform.system() == 'Windows'
 OVERRIDE_HOSTNAME = None # Force to use this hostname
 ALLOW_GPU = False
 LOAD_MODIFIER = 0 # amount to add/subtract from load
 
+LOG_FORMAT = '%(asctime)s %(levelname)-9s openrqd-%(module)-10s %(message)s'
+CONSOLE_LOG_LEVEL = logging.DEBUG
+FILE_LOG_LEVEL = logging.WARNING  # Equal to or greater than the consoleLevel
+
 if subprocess.getoutput('/bin/su --help').find('session-command') != -1:
     SU_ARGUMENT = '--session-command'
 else:
@@ -138,8 +143,8 @@
         else:
             ConfigParser = configparser.RawConfigParser
         config = ConfigParser()
-        logging.info('Loading config %s', CONFIG_FILE)
         config.read(CONFIG_FILE)
+        logging.warning('Loading config %s', CONFIG_FILE)
 
         if config.has_option(__section, "RQD_GRPC_PORT"):
             RQD_GRPC_PORT = config.getint(__section, "RQD_GRPC_PORT")
@@ -173,8 +178,16 @@
             DEFAULT_FACILITY = config.get(__section, "DEFAULT_FACILITY")
         if config.has_option(__section, "LAUNCH_FRAME_USER_GID"):
             LAUNCH_FRAME_USER_GID = config.getint(__section, "LAUNCH_FRAME_USER_GID")
+        if config.has_option(__section, "CONSOLE_LOG_LEVEL"):
+            level = config.get(__section, "CONSOLE_LOG_LEVEL")
+            CONSOLE_LOG_LEVEL = logging.getLevelName(level)
+        if config.has_option(__section, "FILE_LOG_LEVEL"):
+            level = config.get(__section, "FILE_LOG_LEVEL")
+            FILE_LOG_LEVEL = logging.getLevelName(level)
 # pylint: disable=broad-except
 except Exception as e:
     logging.warning(
         "Failed to read values from config file %s due to %s at %s",
         CONFIG_FILE, e, traceback.extract_tb(sys.exc_info()[2]))
+
+logging.warning("CUEBOT_HOSTNAME: %s", CUEBOT_HOSTNAME)

rqd/rqd/rqcore.py

@@ -22,7 +22,7 @@
 
 from builtins import str
 from builtins import object
-import logging as log
+import logging
 import os
 import platform
 import random
@@ -46,6 +46,8 @@
 
 INT32_MAX = 2147483647
 INT32_MIN = -2147483648
+log = logging.getLogger(__name__)
+
 
 class FrameAttendantThread(threading.Thread):
     """Once a frame has been received and checked by RQD, this class handles
@@ -582,7 +584,7 @@ def __init__(self, optNimbyoff=False):
             booked_cores=0,
         )
 
-        self.nimby = rqd.rqnimby.Nimby(self)
+        self.nimby = rqd.rqnimby.NimbyFactory.getNimby(self)
 
         self.machine = rqd.rqmachine.Machine(self, self.cores)
 
@@ -614,6 +616,7 @@ def start(self):
                     log.warning('OVERRIDE_NIMBY is False, Nimby startup has been disabled')
             else:
                 self.nimbyOn()
+                self.onNimbyLock()
         elif rqd.rqconstants.OVERRIDE_NIMBY:
             log.warning('Nimby startup has been triggered by OVERRIDE_NIMBY')
             self.nimbyOn()
@@ -836,7 +839,12 @@ def launchFrame(self, runFrame):
             raise rqd.rqexceptions.CoreReservationFailureException(err)
 
         if self.nimby.locked and not runFrame.ignore_nimby:
-            err = "Not launching, rqd is lockNimby"
+            err = "Not launching, rqd is lockNimby and not Ignore Nimby"
+            log.info(err)
+            raise rqd.rqexceptions.CoreReservationFailureException(err)
+
+        if rqd.rqconstants.OVERRIDE_NIMBY and self.nimby.isNimbyActive():
+            err = "Not launching, rqd is lockNimby and User is Active"
             log.info(err)
             raise rqd.rqexceptions.CoreReservationFailureException(err)
 
@@ -913,6 +921,7 @@ def shutdownRqdNow(self):
 
     def shutdownRqdIdle(self):
         """When machine is idle, shutdown RQD"""
+        log.info("shutdownRqdIdle")
         self.lockAll()
         self.__whenIdle = True
         self.sendStatusReport()
@@ -921,11 +930,13 @@ def shutdownRqdIdle(self):
 
     def restartRqdNow(self):
         """Kill all running frames and restart RQD"""
+        log.info("RestartRqdNow")
         self.__respawn = True
         self.shutdownRqdNow()
 
     def restartRqdIdle(self):
         """When machine is idle, restart RQD"""
+        log.info("RestartRqdIdle")
         self.lockAll()
         self.__whenIdle = True
         self.__respawn = True

rqd/rqd/rqdservicers.py

@@ -20,14 +20,17 @@
 from __future__ import print_function
 from __future__ import division
 
-import logging as log
+import logging
 
 import grpc
 
 import rqd.compiled_proto.rqd_pb2
 import rqd.compiled_proto.rqd_pb2_grpc
 
 
+log = logging.getLogger(__name__)
+
+
 class RqdInterfaceServicer(rqd.compiled_proto.rqd_pb2_grpc.RqdInterfaceServicer):
     """Service interface for RqdStatic gRPC definition."""
 

rqd/rqd/rqmachine.py

@@ -31,7 +31,7 @@
 
 import ctypes
 import errno
-import logging as log
+import logging
 import math
 import os
 import platform
@@ -64,6 +64,7 @@
 import rqd.rqutil
 
 
+log = logging.getLogger(__name__)
 KILOBYTE = 1024
 
 

rqd/rqd/rqnetwork.py

@@ -25,7 +25,7 @@
 from random import shuffle
 import abc
 import atexit
-import logging as log
+import logging
 import os
 import platform
 import subprocess
@@ -41,6 +41,9 @@
 import rqd.rqutil
 
 
+log = logging.getLogger(__name__)
+
+
 class RunningFrame(object):
     """Represents a running frame."""
 
@@ -101,7 +104,7 @@ def status(self):
 
     def kill(self, message=""):
         """Kills the frame"""
-        log.info("Request recieved: kill")
+        log.info("Request received: kill")
         if self.frameAttendantThread is None:
             log.warning(
                 "Kill requested before frameAttendantThread is created for: %s", self.frameId)