/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-03-15 19:59:49 UTC
  • Revision ID: teddy@recompile.se-20190315195949-km03h309lrqwl3ym
mandos-ctl: Bug fix: always shutdown logging.

* mandos-ctl: Shutdown logging at application exit.

Show diffs side-by-side

added added

removed removed

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