/mandos/trunk

To get this branch, use:
bzr branch http://bzr.recompile.se/loggerhead/mandos/trunk

« back to all changes in this revision

Viewing changes to mandos-monitor

  • Committer: Teddy Hogeborn
  • Date: 2019-11-03 18:44:41 UTC
  • Revision ID: teddy@recompile.se-20191103184441-1vhjuf06hjqgfohh
mandos-monitor: Use Python's standard loggging module

* mandos-monitor: Use Python's standard loggging module, also for
                  warnings.  Suppress BytesWarning from urwid when
                  exiting.
  (log): New global logger object.  This replaces UserInterface
        log_message().
  (MandosClientWidget.__init__): Remove "logger" argument.
  (MandosClientWidget.using_timer): Wrap self.update_timer using new
                                    glib_safely() function.
  (glib_safely): New function to log any exceptions instead of letting
                 exceptions propagate up to GLib.
  (UserInterface.__init__): Remove "log_level" argument.  Set new
                            "loghandler" attribute, instance of new
                            "UILogHandler".
  (UserInterface.log_message): Removed.
  (UserInterface.log_message_raw): Renamed to "add_log_line"; all
                                   callers changed.  Also fix
                                   off-by-one error in max_log_length
                                   logic.
  (UserInterface.run): Add self.loghandler to logger "log". Wrap
                       self.process_input using new glib_safely()
                       function.
  (UserInterface.stop): Remove self.loghandler from logger "log".
  (UserInterface.process_input): Make verbosity toggle affect log
                                 level of logger "log".
  (UILogHandler): New.

Show diffs side-by-side

added added

removed removed

Lines of Context:
mandos-monitor
51
51
if sys.version_info.major == 2:
52
52
    str = unicode
53
53
 
 
54
log = logging.getLogger(os.path.basename(sys.argv[0]))
 
55
logging.basicConfig(level="NOTSET", # Show all messages
 
56
                    format="%(message)s") # Show basic log messages
 
57
 
 
58
logging.captureWarnings(True)   # Show warnings via the logging system
 
59
 
54
60
locale.setlocale(locale.LC_ALL, '')
55
61
 
56
62
logging.getLogger('dbus.proxies').setLevel(logging.CRITICAL)
122
128
    """
123
129
 
124
130
    def __init__(self, server_proxy_object=None, update_hook=None,
125
 
                 delete_hook=None, logger=None, **kwargs):
 
131
                 delete_hook=None, **kwargs):
126
132
        # Called on update
127
133
        self.update_hook = update_hook
128
134
        # Called on delete
129
135
        self.delete_hook = delete_hook
130
136
        # Mandos Server proxy object
131
137
        self.server_proxy_object = server_proxy_object
132
 
        # Logger
133
 
        self.logger = logger
134
138
 
135
139
        self._update_timer_callback_tag = None
136
140
 
163
167
                                         self.rejected,
164
168
                                         client_interface,
165
169
                                         byte_arrays=True))
166
 
        self.logger('Created client {}'
167
 
                    .format(self.properties["Name"]), level=0)
 
170
        log.debug('Created client %s', self.properties["Name"])
168
171
 
169
172
    def using_timer(self, flag):
170
173
        """Call this method with True or False when timer should be
172
175
        """
173
176
        if flag and self._update_timer_callback_tag is None:
174
177
            # Will update the shown timer value every second
175
 
            self._update_timer_callback_tag = (GLib.timeout_add
176
 
                                               (1000,
177
 
                                                self.update_timer))
 
178
            self._update_timer_callback_tag = (
 
179
                GLib.timeout_add(1000,
 
180
                                 glib_safely(self.update_timer)))
178
181
        elif not (flag or self._update_timer_callback_tag is None):
179
182
            GLib.source_remove(self._update_timer_callback_tag)
180
183
            self._update_timer_callback_tag = None
181
184
 
182
185
    def checker_completed(self, exitstatus, condition, command):
183
186
        if exitstatus == 0:
184
 
            self.logger('Checker for client {} (command "{}")'
185
 
                        ' succeeded'.format(self.properties["Name"],
186
 
                                            command), level=0)
 
187
            log.debug('Checker for client %s (command "%s")'
 
188
                      ' succeeded', self.properties["Name"], command)
187
189
            self.update()
188
190
            return
189
191
        # Checker failed
190
192
        if os.WIFEXITED(condition):
191
 
            self.logger('Checker for client {} (command "{}") failed'
192
 
                        ' with exit code {}'
193
 
                        .format(self.properties["Name"], command,
194
 
                                os.WEXITSTATUS(condition)))
 
193
            log.info('Checker for client %s (command "%s") failed'
 
194
                     ' with exit code %d', self.properties["Name"],
 
195
                     command, os.WEXITSTATUS(condition))
195
196
        elif os.WIFSIGNALED(condition):
196
 
            self.logger('Checker for client {} (command "{}") was'
197
 
                        ' killed by signal {}'
198
 
                        .format(self.properties["Name"], command,
199
 
                                os.WTERMSIG(condition)))
 
197
            log.info('Checker for client %s (command "%s") was'
 
198
                     ' killed by signal %d', self.properties["Name"],
 
199
                     command, os.WTERMSIG(condition))
200
200
        self.update()
201
201
 
202
202
    def checker_started(self, command):
203
203
        """Server signals that a checker started."""
204
 
        self.logger('Client {} started checker "{}"'
205
 
                    .format(self.properties["Name"],
206
 
                            command), level=0)
 
204
        log.debug('Client %s started checker "%s"',
 
205
                  self.properties["Name"], command)
207
206
 
208
207
    def got_secret(self):
209
 
        self.logger('Client {} received its secret'
210
 
                    .format(self.properties["Name"]))
 
208
        log.info("Client %s received its secret",
 
209
                 self.properties["Name"])
211
210
 
212
211
    def need_approval(self, timeout, default):
213
212
        if not default:
214
 
            message = 'Client {} needs approval within {} seconds'
 
213
            message = "Client %s needs approval within %f seconds"
215
214
        else:
216
 
            message = 'Client {} will get its secret in {} seconds'
217
 
        self.logger(message.format(self.properties["Name"],
218
 
                                   timeout/1000))
 
215
            message = "Client %s will get its secret in %f seconds"
 
216
        log.info(message, self.properties["Name"], timeout/1000)
219
217
 
220
218
    def rejected(self, reason):
221
 
        self.logger('Client {} was rejected; reason: {}'
222
 
                    .format(self.properties["Name"], reason))
 
219
        log.info("Client %s was rejected; reason: %s",
 
220
                 self.properties["Name"], reason)
223
221
 
224
222
    def selectable(self):
225
223
        """Make this a "selectable" widget.
387
385
            self.update()
388
386
 
389
387
 
 
388
def glib_safely(func, retval=True):
 
389
    def safe_func(*args, **kwargs):
 
390
        try:
 
391
            return func(*args, **kwargs)
 
392
        except Exception:
 
393
            log.exception("")
 
394
            return retval
 
395
    return safe_func
 
396
 
 
397
 
390
398
class ConstrainedListBox(urwid.ListBox):
391
399
    """Like a normal urwid.ListBox, but will consume all "up" or
392
400
    "down" key presses, thus not allowing any containing widgets to
404
412
    """This is the entire user interface - the whole screen
405
413
    with boxes, lists of client widgets, etc.
406
414
    """
407
 
    def __init__(self, max_log_length=1000, log_level=1):
 
415
    def __init__(self, max_log_length=1000):
408
416
        DBusGMainLoop(set_as_default=True)
409
417
 
410
418
        self.screen = urwid.curses_display.Screen()
447
455
        self.log = urwid.SimpleListWalker([])
448
456
        self.max_log_length = max_log_length
449
457
 
450
 
        self.log_level = log_level
451
 
 
452
458
        # We keep a reference to the log widget so we can remove it
453
459
        # from the ListWalker without it getting destroyed
454
460
        self.logbox = ConstrainedListBox(self.log)
458
464
        self.log_visible = True
459
465
        self.log_wrap = "any"
460
466
 
 
467
        self.loghandler = UILogHandler(self)
 
468
 
461
469
        self.rebuild()
462
 
        self.log_message_raw(("bold",
463
 
                              "Mandos Monitor version " + version))
464
 
        self.log_message_raw(("bold",
465
 
                              "q: Quit  ?: Help"))
 
470
        self.add_log_line(("bold",
 
471
                           "Mandos Monitor version " + version))
 
472
        self.add_log_line(("bold", "q: Quit  ?: Help"))
466
473
 
467
474
        self.busname = domain + '.Mandos'
468
475
        self.main_loop = GLib.MainLoop()
469
476
 
470
477
    def client_not_found(self, key_id, address):
471
 
        self.log_message("Client with address {} and key ID {} could"
472
 
                         " not be found".format(address, key_id))
 
478
        log.info("Client with address %s and key ID %s could"
 
479
                 " not be found", address, key_id)
473
480
 
474
481
    def rebuild(self):
475
482
        """This rebuilds the User Interface.
486
493
            self.uilist.append(self.logbox)
487
494
        self.topwidget = urwid.Pile(self.uilist)
488
495
 
489
 
    def log_message(self, message, level=1):
490
 
        """Log message formatted with timestamp"""
491
 
        if level < self.log_level:
492
 
            return
493
 
        timestamp = datetime.datetime.now().isoformat()
494
 
        self.log_message_raw("{}: {}".format(timestamp, message),
495
 
                             level=level)
496
 
 
497
 
    def log_message_raw(self, markup, level=1):
498
 
        """Add a log message to the log buffer."""
499
 
        if level < self.log_level:
500
 
            return
 
496
    def add_log_line(self, markup):
501
497
        self.log.append(urwid.Text(markup, wrap=self.log_wrap))
502
498
        if self.max_log_length:
503
499
            if len(self.log) > self.max_log_length:
504
 
                del self.log[0:len(self.log)-self.max_log_length-1]
 
500
                del self.log[0:(len(self.log) - self.max_log_length)]
505
501
        self.logbox.set_focus(len(self.logbox.body.contents)-1,
506
502
                              coming_from="above")
507
503
        self.refresh()
510
506
        """Toggle visibility of the log buffer."""
511
507
        self.log_visible = not self.log_visible
512
508
        self.rebuild()
513
 
        self.log_message("Log visibility changed to: {}"
514
 
                         .format(self.log_visible), level=0)
 
509
        log.debug("Log visibility changed to: %s", self.log_visible)
515
510
 
516
511
    def change_log_display(self):
517
512
        """Change type of log display.
522
517
            self.log_wrap = "clip"
523
518
        for textwidget in self.log:
524
519
            textwidget.set_wrap_mode(self.log_wrap)
525
 
        self.log_message("Wrap mode: {}".format(self.log_wrap),
526
 
                         level=0)
 
520
        log.debug("Wrap mode: %s", self.log_wrap)
527
521
 
528
522
    def find_and_remove_client(self, path, interfaces):
529
523
        """Find a client by its object path and remove it.
537
531
            client = self.clients_dict[path]
538
532
        except KeyError:
539
533
            # not found?
540
 
            self.log_message("Unknown client {!r} removed"
541
 
                             .format(path))
 
534
            log.warning("Unknown client %s removed", path)
542
535
            return
543
536
        client.delete()
544
537
 
557
550
            proxy_object=client_proxy_object,
558
551
            update_hook=self.refresh,
559
552
            delete_hook=self.remove_client,
560
 
            logger=self.log_message,
561
553
            properties=dict(ifs_and_props[client_interface])),
562
554
                        path=path)
563
555
 
583
575
 
584
576
    def run(self):
585
577
        """Start the main loop and exit when it's done."""
 
578
        log.addHandler(self.loghandler)
 
579
        self.orig_log_propagate = log.propagate
 
580
        log.propagate = False
 
581
        self.orig_log_level = log.level
 
582
        log.setLevel("INFO")
586
583
        self.bus = dbus.SystemBus()
587
584
        mandos_dbus_objc = self.bus.get_object(
588
585
            self.busname, "/", follow_name_owner_changes=True)
592
589
            mandos_clients = (self.mandos_serv
593
590
                              .GetAllClientsWithProperties())
594
591
            if not mandos_clients:
595
 
                self.log_message_raw(("bold",
596
 
                                      "Note: Server has no clients."))
 
592
                log.warning("Note: Server has no clients.")
597
593
        except dbus.exceptions.DBusException:
598
 
            self.log_message_raw(("bold",
599
 
                                  "Note: No Mandos server running."))
 
594
            log.warning("Note: No Mandos server running.")
600
595
            mandos_clients = dbus.Dictionary()
601
596
 
602
597
        (self.mandos_serv
622
617
                proxy_object=client_proxy_object,
623
618
                properties=client,
624
619
                update_hook=self.refresh,
625
 
                delete_hook=self.remove_client,
626
 
                logger=self.log_message),
 
620
                delete_hook=self.remove_client),
627
621
                            path=path)
628
622
 
629
623
        self.refresh()
631
625
            GLib.io_add_watch(
632
626
                GLib.IOChannel.unix_new(sys.stdin.fileno()),
633
627
                GLib.PRIORITY_DEFAULT, GLib.IO_IN,
634
 
                self.process_input))
 
628
                glib_safely(self.process_input)))
635
629
        self.main_loop.run()
636
630
        # Main loop has finished, we should close everything now
637
631
        GLib.source_remove(self._input_callback_tag)
641
635
 
642
636
    def stop(self):
643
637
        self.main_loop.quit()
 
638
        log.removeHandler(self.loghandler)
 
639
        log.propagate = self.orig_log_propagate
644
640
 
645
641
    def process_input(self, source, condition):
646
642
        keys = self.screen.get_input()
679
675
                if not self.log_visible:
680
676
                    self.log_visible = True
681
677
                    self.rebuild()
682
 
                self.log_message_raw(("bold",
683
 
                                      "  ".
684
 
                                      join(("q: Quit",
685
 
                                            "?: Help",
686
 
                                            "l: Log window toggle",
687
 
                                            "TAB: Switch window",
688
 
                                            "w: Wrap (log lines)",
689
 
                                            "v: Toggle verbose log",
690
 
                                            ))))
691
 
                self.log_message_raw(("bold",
692
 
                                      "  "
693
 
                                      .join(("Clients:",
694
 
                                             "+: Enable",
695
 
                                             "-: Disable",
696
 
                                             "R: Remove",
697
 
                                             "s: Start new checker",
698
 
                                             "S: Stop checker",
699
 
                                             "C: Checker OK",
700
 
                                             "a: Approve",
701
 
                                             "d: Deny"))))
 
678
                self.add_log_line(("bold",
 
679
                                   "  ".join(("q: Quit",
 
680
                                              "?: Help",
 
681
                                              "l: Log window toggle",
 
682
                                              "TAB: Switch window",
 
683
                                              "w: Wrap (log lines)",
 
684
                                              "v: Toggle verbose log",
 
685
                                   ))))
 
686
                self.add_log_line(("bold",
 
687
                                   "  ".join(("Clients:",
 
688
                                              "+: Enable",
 
689
                                              "-: Disable",
 
690
                                              "R: Remove",
 
691
                                              "s: Start new checker",
 
692
                                              "S: Stop checker",
 
693
                                              "C: Checker OK",
 
694
                                              "a: Approve",
 
695
                                              "d: Deny",
 
696
                                   ))))
702
697
                self.refresh()
703
698
            elif key == "tab":
704
699
                if self.topwidget.get_focus() is self.logbox:
707
702
                    self.topwidget.set_focus(self.logbox)
708
703
                self.refresh()
709
704
            elif key == "v":
710
 
                if self.log_level == 0:
711
 
                    self.log_level = 1
712
 
                    self.log_message("Verbose mode: Off")
 
705
                if log.level < logging.INFO:
 
706
                    log.setLevel(logging.INFO)
 
707
                    log.info("Verbose mode: Off")
713
708
                else:
714
 
                    self.log_level = 0
715
 
                    self.log_message("Verbose mode: On")
 
709
                    log.setLevel(logging.NOTSET)
 
710
                    log.info("Verbose mode: On")
716
711
            # elif (key == "end" or key == "meta >" or key == "G"
717
712
            #       or key == ">"):
718
713
            #     pass            # xxx end-of-buffer
737
732
        return True
738
733
 
739
734
 
 
735
class UILogHandler(logging.Handler):
 
736
    def __init__(self, ui, *args, **kwargs):
 
737
        self.ui = ui
 
738
        super(UILogHandler, self).__init__(*args, **kwargs)
 
739
        self.setFormatter(
 
740
            logging.Formatter("%(asctime)s: %(message)s"))
 
741
    def emit(self, record):
 
742
        msg = self.format(record)
 
743
        if record.levelno > logging.INFO:
 
744
            msg = ("bold", msg)
 
745
        self.ui.add_log_line(msg)
 
746
 
 
747
 
740
748
ui = UserInterface()
741
749
try:
742
750
    ui.run()
743
751
except KeyboardInterrupt:
744
 
    ui.screen.stop()
745
 
except Exception as e:
746
 
    ui.log_message(str(e))
747
 
    ui.screen.stop()
 
752
    with warnings.catch_warnings():
 
753
        warnings.filterwarnings("ignore", "", BytesWarning)
 
754
        ui.screen.stop()
 
755
except Exception:
 
756
    with warnings.catch_warnings():
 
757
        warnings.filterwarnings("ignore", "", BytesWarning)
 
758
        ui.screen.stop()
748
759
    raise