/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: 2024-11-22 20:28:54 UTC
  • Revision ID: teddy@recompile.se-20241122202854-dycuf117byxhxl32
mandos-monitor: Avoid debug messages from urwid

Avoid debug messages from urwid.  Any logging output before the screen
has been set up will mangle the screen.

* mandos-monitor: When setting up logging, set urwid to only show log
  messages of level INFO or above.

(Thanks to an anonymous contributor for reporting this.)

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