/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 at recompile
  • Date: 2020-02-05 20:32:33 UTC
  • Revision ID: teddy@recompile.se-20200205203233-450ojm36jseglq4m
Server: Stagger checker runs when creating clients

To avoid checkers for all clients all running at the same time
periodically, schedule every initially scheduled future checker to run
at a time in the future a random amount of the interval, from the
current time.

* mandos (Client.init_checker): Schedule the first scheduled future
  run of a checker to be a randomly chosen amount of this client's
  "interval" (instead of a full interval).

Show diffs side-by-side

added added

removed removed

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