Merge pull request #377 from pupil-labs/IPC_logging

Ipc logging

pupil_src/capture/eye.py

@@ -37,35 +37,30 @@ def eye(pupil_queue, timebase, pipe_to_world, is_alive_flag, user_dir, version,
     """
     is_alive = Is_Alive_Manager(is_alive_flag)
     with is_alive:
+        #logging setup: We stream all log records to the world process.
         import logging
-        # Set up root logger for this process before doing imports of logged modules.
+        import zmq
+        ctx = zmq.Context()
+        pub = ctx.socket(zmq.PUB)
+        pub.connect('tcp://127.0.0.1:502020')
+
+        class ZMQ_handler(logging.Handler):
+            def emit(self, record):
+                pub.send_pyobj(record)
+
         logger = logging.getLogger()
-        logger.setLevel(logging.INFO)
-        # remove inherited handlers
         logger.handlers = []
-        # create file handler which logs even debug messages
-        fh = logging.FileHandler(os.path.join(user_dir,'eye%s.log'%eye_id),mode='w')
-        # fh.setLevel(logging.DEBUG)
-        # create console handler with a higher log level
-        ch = logging.StreamHandler()
-        ch.setLevel(logger.level+10)
-        # create formatter and add it to the handlers
-        formatter = logging.Formatter('Eye'+str(eye_id)+' Process: %(asctime)s - %(name)s - %(levelname)s - %(message)s')
-        fh.setFormatter(formatter)
-        formatter = logging.Formatter('EYE'+str(eye_id)+' Process [%(levelname)s] %(name)s : %(message)s')
-        ch.setFormatter(formatter)
-        # add the handlers to the logger
-        logger.addHandler(fh)
-        logger.addHandler(ch)
-        #silence noisy modules
-        logging.getLogger("OpenGL").setLevel(logging.ERROR)
+        logger.setLevel(logging.INFO)
+        logger.addHandler(ZMQ_handler())
+
         # create logger for the context of this function
         logger = logging.getLogger(__name__)
 
+        #silence noisy modules
+        logging.getLogger("OpenGL").setLevel(logging.ERROR)
 
         # We deferr the imports becasue of multiprocessing.
         # Otherwise the world process each process also loads the other imports.
-
         #general imports
         import numpy as np
         import cv2
@@ -486,9 +481,7 @@ def window_should_update():
         glfw.glfwDestroyWindow(main_window)
         glfw.glfwTerminate()
         cap.close()
-
-
-        logger.debug("Process done")
+        logger.info("Process Shutting down.")
 
 def eye_profiled(pupil_queue, timebase, pipe_to_world, is_alive_flag, user_dir, version, eye_id, cap_src):
     import cProfile,subprocess,os

pupil_src/capture/main.py

@@ -75,14 +75,16 @@ def main():
     com_eye_ends = com0[1],com1[1]
 
 
-    p_world = Process(target=world,args=(pupil_queue,
-                                        timebase,
-                                        cmd_world_end,
-                                        com_world_ends,
-                                        eyes_are_alive,
-                                        user_dir,
-                                        app_version,
-                                        video_sources['world'] ))
+    p_world = Process(target=world,
+                      name= 'world',
+                      args=(pupil_queue,
+                            timebase,
+                            cmd_world_end,
+                            com_world_ends,
+                            eyes_are_alive,
+                            user_dir,
+                            app_version,
+                            video_sources['world'] ))
     p_world.start()
 
     while True:
@@ -92,14 +94,16 @@ def main():
             break
         else:
             eye_id = cmd
-            p_eye = Process(target=eye,args=(pupil_queue,
-                                            timebase,
-                                            com_eye_ends[eye_id],
-                                            eyes_are_alive[eye_id],
-                                            user_dir,
-                                            app_version,
-                                            eye_id,
-                                            video_sources['eye%s'%eye_id] ))
+            p_eye = Process(target=eye,
+                            name='eye%s'%eye_id,
+                            args=(pupil_queue,
+                                timebase,
+                                com_eye_ends[eye_id],
+                                eyes_are_alive[eye_id],
+                                user_dir,
+                                app_version,
+                                eye_id,
+                                video_sources['eye%s'%eye_id] ))
             p_eye.start()
 
     for p in active_children(): p.join()

pupil_src/capture/world.py

@@ -13,7 +13,7 @@
 class Global_Container(object):
     pass
 
-def world(pupil_queue,timebase,lauchner_pipe,eye_pipes,eyes_are_alive,user_dir,version,cap_src):
+def world(pupil_queue,timebase,launcher_pipe,eye_pipes,eyes_are_alive,user_dir,version,cap_src):
     """world
     Creates a window, gl context.
     Grabs images from a capture.
@@ -25,32 +25,51 @@ def world(pupil_queue,timebase,lauchner_pipe,eye_pipes,eyes_are_alive,user_dir,v
     # Set up root logger for this process before doing imports of logged modules.
     logger = logging.getLogger()
     logger.setLevel(logging.INFO)
+    #silence noisy modules
+    logging.getLogger("OpenGL").setLevel(logging.ERROR)
+    # create formatter
+    formatter = logging.Formatter('%(processName)s - [%(levelname)s] %(name)s : %(message)s')
     # create file handler which logs even debug messages
-    fh = logging.FileHandler(os.path.join(user_dir,'world.log'),mode='w')
+    fh = logging.FileHandler(os.path.join(user_dir,'capture.log'),mode='w')
     fh.setLevel(logger.level)
+    fh.setFormatter(formatter)
     # create console handler with a higher log level
     ch = logging.StreamHandler()
     ch.setLevel(logger.level+10)
-    # create formatter and add it to the handlers
-    formatter = logging.Formatter('World Process: %(asctime)s - %(name)s - %(levelname)s - %(message)s')
-    fh.setFormatter(formatter)
-    formatter = logging.Formatter('WORLD Process [%(levelname)s] %(name)s : %(message)s')
     ch.setFormatter(formatter)
     # add the handlers to the logger
     logger.addHandler(fh)
     logger.addHandler(ch)
-    #silence noisy modules
-    logging.getLogger("OpenGL").setLevel(logging.ERROR)
+
+
+    #setup thread to recv log recrods from other processes.
+    def log_loop(logging):
+        import zmq
+        ctx = zmq.Context()
+        sub = ctx.socket(zmq.SUB)
+        sub.bind('tcp://127.0.0.1:502020')
+        sub.setsockopt(zmq.SUBSCRIBE, "")
+        while True:
+            record = sub.recv_pyobj()
+            logger = logging.getLogger(record.name)
+            logger.handle(record)
+
+    import threading
+    log_thread = threading.Thread(target=log_loop, args=(logging,))
+    log_thread.setDaemon(True)
+    log_thread.start()
+
+
     # create logger for the context of this function
     logger = logging.getLogger(__name__)
 
 
-    # We deferr the imports becasue of multiprocessing.
+    # We defer the imports because of multiprocessing.
     # Otherwise the world process each process also loads the other imports.
-    # This is not harmfull but unnessasary.
+    # This is not harmful but unnecessary.
 
     #general imports
-    from time import time
+    from time import time,sleep
     import numpy as np
 
     #display
@@ -112,7 +131,7 @@ def world(pupil_queue,timebase,lauchner_pipe,eye_pipes,eyes_are_alive,user_dir,v
     g_pool.app = 'capture'
     g_pool.pupil_queue = pupil_queue
     g_pool.timebase = timebase
-    # g_pool.lauchner_pipe = lauchner_pipe
+    # g_pool.launcher_pipe = launcher_pipe
     g_pool.eye_pipes = eye_pipes
     g_pool.eyes_are_alive = eyes_are_alive
 
@@ -188,7 +207,7 @@ def get_dt():
     except CameraCaptureError:
         logger.error("Could not retrieve image from capture")
         cap.close()
-        lauchner_pipe.send("Exit")
+        launcher_pipe.send("Exit")
         return
 
 
@@ -215,7 +234,7 @@ def launch_eye_process(eye_id,blocking=False):
         if eyes_are_alive[eye_id].value:
             logger.error("Eye%s process already running."%eye_id)
             return
-        lauchner_pipe.send(eye_id)
+        launcher_pipe.send(eye_id)
         eye_pipes[eye_id].send( ('Set_Detection_Mapping_Mode',g_pool.detection_mapping_mode) )
 
         if blocking:
@@ -229,7 +248,8 @@ def stop_eye_process(eye_id,blocking=False):
         if eyes_are_alive[eye_id].value:
             eye_pipes[eye_id].send('Exit')
             if blocking:
-                raise NotImplementedError()
+                while eyes_are_alive[eye_id].value:
+                    sleep(.1)
 
     def start_stop_eye(eye_id,make_alive):
         if make_alive:
@@ -461,19 +481,19 @@ def set_detection_mapping_mode(new_mode):
     g_pool.capture.close()
 
     #shut down eye processes:
-    stop_eye_process(0)
-    stop_eye_process(1)
+    stop_eye_process(0,blocking = True)
+    stop_eye_process(1,blocking = True)
 
     #shut down laucher
-    lauchner_pipe.send("Exit")
+    launcher_pipe.send("Exit")
 
-    logger.debug("world process done")
+    logger.info("Process Shutting down.")
 
-def world_profiled(pupil_queue,timebase,lauchner_pipe,eye_pipes,eyes_are_alive,user_dir,version,cap_src):
+def world_profiled(pupil_queue,timebase,launcher_pipe,eye_pipes,eyes_are_alive,user_dir,version,cap_src):
     import cProfile,subprocess,os
     from world import world
-    cProfile.runctx("world(pupil_queue,timebase,lauchner_pipe,eye_pipes,eyes_are_alive,user_dir,version,cap_src)",{'pupil_queue':pupil_queue,'timebase':timebase,'lauchner_pipe':lauchner_pipe,'eye_pipes':eye_pipes,'eyes_are_alive':eyes_are_alive,'user_dir':user_dir,'version':version,'cap_src':cap_src},locals(),"world.pstats")
+    cProfile.runctx("world(pupil_queue,timebase,launcher_pipe,eye_pipes,eyes_are_alive,user_dir,version,cap_src)",{'pupil_queue':pupil_queue,'timebase':timebase,'launcher_pipe':launcher_pipe,'eye_pipes':eye_pipes,'eyes_are_alive':eyes_are_alive,'user_dir':user_dir,'version':version,'cap_src':cap_src},locals(),"world.pstats")
     loc = os.path.abspath(__file__).rsplit('pupil_src', 1)
     gprof2dot_loc = os.path.join(loc[0], 'pupil_src', 'shared_modules','gprof2dot.py')
     subprocess.call("python "+gprof2dot_loc+" -f pstats world.pstats | dot -Tpng -o world_cpu_time.png", shell=True)
-    print "created cpu time graph for world process. Please check out the png next to the world.py file"
+    print "created cpu time graph for world process. Please check out the png next to the world.py file"

pupil_src/shared_modules/log_display.py

@@ -84,10 +84,10 @@ def gl_display(self):
             for record in self.rendered_log:
                 self.glfont.set_color_float((0.,0.,0.,1.))
                 self.glfont.set_blur(10.5)
-                self.glfont.draw_limited_text(self.window_size[0]/2.,y,str(record.msg),self.window_size[0]*0.8)
+                self.glfont.draw_limited_text(self.window_size[0]/2.,y,str(record.processName.upper())+': '+str(record.msg),self.window_size[0]*0.8)
                 self.glfont.set_blur(0.96)
                 self.glfont.set_color_float(color_from_level(record.levelname))
-                self.glfont.draw_limited_text(self.window_size[0]/2.,y,str(record.msg),self.window_size[0]*0.8)
+                self.glfont.draw_limited_text(self.window_size[0]/2.,y,str(record.processName.upper())+': '+str(record.msg),self.window_size[0]*0.8)
                 y +=lineh
             pop_ortho()
             self.tex.pop()

pupil_src/shared_modules/video_capture/uvc_capture.py

@@ -197,7 +197,7 @@ def settings(self,settings):
             try:
                 c.value = settings['uvc_controls'][c.display_name]
             except KeyError as e:
-                logger.info('No UVC setting "%s" found from settings.'%c.display_name)
+                logger.debug('No UVC setting "%s" found from settings.'%c.display_name)
     @property
     def frame_size(self):
         return self.capture.frame_size
@@ -326,6 +326,5 @@ def close(self):
         self.deinit_gui()
         # self.capture.close()
         del self.capture
-        logger.info("Capture released")