/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

  • Committer: Teddy Hogeborn
  • Date: 2024-11-03 16:01:18 UTC
  • Revision ID: teddy@recompile.se-20241103160118-74csxmbgidxt9cx6
Make binary directory configurable

Reportedly, Arch Linux uses /bin for all binaries, not /sbin.
Therefore, make binary directory configurable.

From: Erich Eckner <mandos@eckner.net>
Signed-off-by: Teddy Hogeborn <teddy@recompile.se>

Show diffs side-by-side

added added

removed removed

Lines of Context:
1
1
#!/usr/bin/python3 -bI
2
 
# -*- mode: python; after-save-hook: (lambda () (let ((command (if (fboundp 'file-local-name) (file-local-name (buffer-file-name)) (or (file-remote-p (buffer-file-name) 'localname) (buffer-file-name))))) (if (= (progn (if (get-buffer "*Test*") (kill-buffer "*Test*")) (process-file-shell-command (format "%s --check" (shell-quote-argument command)) nil "*Test*")) 0) (let ((w (get-buffer-window "*Test*"))) (if w (delete-window w))) (progn (with-current-buffer "*Test*" (compilation-mode)) (display-buffer "*Test*" '(display-buffer-in-side-window)))))); coding: utf-8 -*-
 
2
# -*- coding: utf-8; lexical-binding: t -*-
3
3
#
4
4
# Mandos server - give out binary blobs to connecting clients.
5
5
#
11
11
# "AvahiService" class, and some lines in "main".
12
12
#
13
13
# Everything else is
14
 
# Copyright © 2008-2020 Teddy Hogeborn
15
 
# Copyright © 2008-2020 Björn Påhlsson
 
14
# Copyright © 2008-2022 Teddy Hogeborn
 
15
# Copyright © 2008-2022 Björn Påhlsson
16
16
#
17
17
# This file is part of Mandos.
18
18
#
31
31
#
32
32
# Contact the authors at <mandos@recompile.se>.
33
33
#
34
 
 
35
34
from __future__ import (division, absolute_import, print_function,
36
35
                        unicode_literals)
37
36
 
40
39
except ImportError:
41
40
    pass
42
41
 
 
42
import sys
 
43
import unittest
 
44
import argparse
 
45
import logging
 
46
import os
43
47
try:
44
48
    import SocketServer as socketserver
45
49
except ImportError:
46
50
    import socketserver
47
51
import socket
48
 
import argparse
49
52
import datetime
50
53
import errno
51
54
try:
52
55
    import ConfigParser as configparser
53
56
except ImportError:
54
57
    import configparser
55
 
import sys
56
58
import re
57
 
import os
58
59
import signal
59
60
import subprocess
60
61
import atexit
61
62
import stat
62
 
import logging
63
63
import logging.handlers
64
64
import pwd
65
65
import contextlib
77
77
import itertools
78
78
import collections
79
79
import codecs
80
 
import unittest
81
80
import random
82
81
import shlex
83
82
 
94
93
if sys.version_info.major == 2:
95
94
    __metaclass__ = type
96
95
    str = unicode
 
96
    input = raw_input
97
97
 
98
98
# Add collections.abc.Callable if it does not exist
99
99
try:
143
143
if sys.version_info < (3, 2):
144
144
    configparser.Configparser = configparser.SafeConfigParser
145
145
 
146
 
version = "1.8.14"
 
146
version = "1.8.17"
147
147
stored_state_file = "clients.pickle"
148
148
 
149
 
logger = logging.getLogger()
 
149
log = logging.getLogger(os.path.basename(sys.argv[0]))
150
150
logging.captureWarnings(True)   # Show warnings via the logging system
151
151
syslogger = None
152
152
 
191
191
    syslogger.setFormatter(logging.Formatter
192
192
                           ("Mandos [%(process)d]: %(levelname)s:"
193
193
                            " %(message)s"))
194
 
    logger.addHandler(syslogger)
 
194
    log.addHandler(syslogger)
195
195
 
196
196
    if debug:
197
197
        console = logging.StreamHandler()
199
199
                                               " [%(process)d]:"
200
200
                                               " %(levelname)s:"
201
201
                                               " %(message)s"))
202
 
        logger.addHandler(console)
203
 
    logger.setLevel(level)
 
202
        log.addHandler(console)
 
203
    log.setLevel(level)
204
204
 
205
205
 
206
206
class PGPError(Exception):
394
394
    def rename(self, remove=True):
395
395
        """Derived from the Avahi example code"""
396
396
        if self.rename_count >= self.max_renames:
397
 
            logger.critical("No suitable Zeroconf service name found"
398
 
                            " after %i retries, exiting.",
399
 
                            self.rename_count)
 
397
            log.critical("No suitable Zeroconf service name found"
 
398
                         " after %i retries, exiting.",
 
399
                         self.rename_count)
400
400
            raise AvahiServiceError("Too many renames")
401
401
        self.name = str(
402
402
            self.server.GetAlternativeServiceName(self.name))
403
403
        self.rename_count += 1
404
 
        logger.info("Changing Zeroconf service name to %r ...",
405
 
                    self.name)
 
404
        log.info("Changing Zeroconf service name to %r ...",
 
405
                 self.name)
406
406
        if remove:
407
407
            self.remove()
408
408
        try:
410
410
        except dbus.exceptions.DBusException as error:
411
411
            if (error.get_dbus_name()
412
412
                == "org.freedesktop.Avahi.CollisionError"):
413
 
                logger.info("Local Zeroconf service name collision.")
 
413
                log.info("Local Zeroconf service name collision.")
414
414
                return self.rename(remove=False)
415
415
            else:
416
 
                logger.critical("D-Bus Exception", exc_info=error)
 
416
                log.critical("D-Bus Exception", exc_info=error)
417
417
                self.cleanup()
418
418
                os._exit(1)
419
419
 
436
436
        self.entry_group_state_changed_match = (
437
437
            self.group.connect_to_signal(
438
438
                "StateChanged", self.entry_group_state_changed))
439
 
        logger.debug("Adding Zeroconf service '%s' of type '%s' ...",
440
 
                     self.name, self.type)
 
439
        log.debug("Adding Zeroconf service '%s' of type '%s' ...",
 
440
                  self.name, self.type)
441
441
        self.group.AddService(
442
442
            self.interface,
443
443
            self.protocol,
450
450
 
451
451
    def entry_group_state_changed(self, state, error):
452
452
        """Derived from the Avahi example code"""
453
 
        logger.debug("Avahi entry group state change: %i", state)
 
453
        log.debug("Avahi entry group state change: %i", state)
454
454
 
455
455
        if state == avahi.ENTRY_GROUP_ESTABLISHED:
456
 
            logger.debug("Zeroconf service established.")
 
456
            log.debug("Zeroconf service established.")
457
457
        elif state == avahi.ENTRY_GROUP_COLLISION:
458
 
            logger.info("Zeroconf service name collision.")
 
458
            log.info("Zeroconf service name collision.")
459
459
            self.rename()
460
460
        elif state == avahi.ENTRY_GROUP_FAILURE:
461
 
            logger.critical("Avahi: Error in group state changed %s",
462
 
                            str(error))
 
461
            log.critical("Avahi: Error in group state changed %s",
 
462
                         str(error))
463
463
            raise AvahiGroupError("State changed: {!s}".format(error))
464
464
 
465
465
    def cleanup(self):
475
475
 
476
476
    def server_state_changed(self, state, error=None):
477
477
        """Derived from the Avahi example code"""
478
 
        logger.debug("Avahi server state change: %i", state)
 
478
        log.debug("Avahi server state change: %i", state)
479
479
        bad_states = {
480
480
            avahi.SERVER_INVALID: "Zeroconf server invalid",
481
481
            avahi.SERVER_REGISTERING: None,
485
485
        if state in bad_states:
486
486
            if bad_states[state] is not None:
487
487
                if error is None:
488
 
                    logger.error(bad_states[state])
 
488
                    log.error(bad_states[state])
489
489
                else:
490
 
                    logger.error(bad_states[state] + ": %r", error)
 
490
                    log.error(bad_states[state] + ": %r", error)
491
491
            self.cleanup()
492
492
        elif state == avahi.SERVER_RUNNING:
493
493
            try:
495
495
            except dbus.exceptions.DBusException as error:
496
496
                if (error.get_dbus_name()
497
497
                    == "org.freedesktop.Avahi.CollisionError"):
498
 
                    logger.info("Local Zeroconf service name"
499
 
                                " collision.")
 
498
                    log.info("Local Zeroconf service name collision.")
500
499
                    return self.rename(remove=False)
501
500
                else:
502
 
                    logger.critical("D-Bus Exception", exc_info=error)
 
501
                    log.critical("D-Bus Exception", exc_info=error)
503
502
                    self.cleanup()
504
503
                    os._exit(1)
505
504
        else:
506
505
            if error is None:
507
 
                logger.debug("Unknown state: %r", state)
 
506
                log.debug("Unknown state: %r", state)
508
507
            else:
509
 
                logger.debug("Unknown state: %r: %r", state, error)
 
508
                log.debug("Unknown state: %r: %r", state, error)
510
509
 
511
510
    def activate(self):
512
511
        """Derived from the Avahi example code"""
962
961
            # key_id() and fingerprint() functions
963
962
            client["key_id"] = (section.get("key_id", "").upper()
964
963
                                .replace(" ", ""))
965
 
            client["fingerprint"] = (section["fingerprint"].upper()
 
964
            client["fingerprint"] = (section.get("fingerprint",
 
965
                                                 "").upper()
966
966
                                     .replace(" ", ""))
 
967
            if not (client["key_id"] or client["fingerprint"]):
 
968
                log.error("Skipping client %s without key_id or"
 
969
                          " fingerprint", client_name)
 
970
                del settings[client_name]
 
971
                continue
967
972
            if "secret" in section:
968
973
                client["secret"] = codecs.decode(section["secret"]
969
974
                                                 .encode("utf-8"),
1010
1015
            self.last_enabled = None
1011
1016
            self.expires = None
1012
1017
 
1013
 
        logger.debug("Creating client %r", self.name)
1014
 
        logger.debug("  Key ID: %s", self.key_id)
1015
 
        logger.debug("  Fingerprint: %s", self.fingerprint)
 
1018
        log.debug("Creating client %r", self.name)
 
1019
        log.debug("  Key ID: %s", self.key_id)
 
1020
        log.debug("  Fingerprint: %s", self.fingerprint)
1016
1021
        self.created = settings.get("created",
1017
1022
                                    datetime.datetime.utcnow())
1018
1023
 
1046
1051
        if getattr(self, "enabled", False):
1047
1052
            # Already enabled
1048
1053
            return
1049
 
        self.expires = datetime.datetime.utcnow() + self.timeout
1050
1054
        self.enabled = True
1051
1055
        self.last_enabled = datetime.datetime.utcnow()
1052
1056
        self.init_checker()
1057
1061
        if not getattr(self, "enabled", False):
1058
1062
            return False
1059
1063
        if not quiet:
1060
 
            logger.info("Disabling client %s", self.name)
 
1064
            log.info("Disabling client %s", self.name)
1061
1065
        if getattr(self, "disable_initiator_tag", None) is not None:
1062
1066
            GLib.source_remove(self.disable_initiator_tag)
1063
1067
            self.disable_initiator_tag = None
1075
1079
    def __del__(self):
1076
1080
        self.disable()
1077
1081
 
1078
 
    def init_checker(self):
1079
 
        # Schedule a new checker to be started an 'interval' from now,
1080
 
        # and every interval from then on.
 
1082
    def init_checker(self, randomize_start=False):
 
1083
        # Schedule a new checker to be started a randomly selected
 
1084
        # time (a fraction of 'interval') from now.  This spreads out
 
1085
        # the startup of checkers over time when the server is
 
1086
        # started.
1081
1087
        if self.checker_initiator_tag is not None:
1082
1088
            GLib.source_remove(self.checker_initiator_tag)
 
1089
        interval_milliseconds = int(self.interval.total_seconds()
 
1090
                                    * 1000)
 
1091
        if randomize_start:
 
1092
            delay_milliseconds = random.randrange(
 
1093
                interval_milliseconds + 1)
 
1094
        else:
 
1095
            delay_milliseconds = interval_milliseconds
1083
1096
        self.checker_initiator_tag = GLib.timeout_add(
1084
 
            random.randrange(int(self.interval.total_seconds() * 1000
1085
 
                                 + 1)),
1086
 
            self.start_checker)
1087
 
        # Schedule a disable() when 'timeout' has passed
 
1097
            delay_milliseconds, self.start_checker, randomize_start)
 
1098
        delay = datetime.timedelta(0, 0, 0, delay_milliseconds)
 
1099
        # A checker might take up to an 'interval' of time, so we can
 
1100
        # expire at the soonest one interval after a checker was
 
1101
        # started.  Since the initial checker is delayed, the expire
 
1102
        # time might have to be extended.
 
1103
        now = datetime.datetime.utcnow()
 
1104
        self.expires = now + delay + self.interval
 
1105
        # Schedule a disable() at expire time
1088
1106
        if self.disable_initiator_tag is not None:
1089
1107
            GLib.source_remove(self.disable_initiator_tag)
1090
1108
        self.disable_initiator_tag = GLib.timeout_add(
1091
 
            int(self.timeout.total_seconds() * 1000), self.disable)
1092
 
        # Also start a new checker *right now*.
1093
 
        self.start_checker()
 
1109
            int((self.expires - now).total_seconds() * 1000),
 
1110
            self.disable)
1094
1111
 
1095
1112
    def checker_callback(self, source, condition, connection,
1096
1113
                         command):
1107
1124
            self.last_checker_status = returncode
1108
1125
            self.last_checker_signal = None
1109
1126
            if self.last_checker_status == 0:
1110
 
                logger.info("Checker for %(name)s succeeded",
1111
 
                            vars(self))
 
1127
                log.info("Checker for %(name)s succeeded", vars(self))
1112
1128
                self.checked_ok()
1113
1129
            else:
1114
 
                logger.info("Checker for %(name)s failed", vars(self))
 
1130
                log.info("Checker for %(name)s failed", vars(self))
1115
1131
        else:
1116
1132
            self.last_checker_status = -1
1117
1133
            self.last_checker_signal = -returncode
1118
 
            logger.warning("Checker for %(name)s crashed?",
1119
 
                           vars(self))
 
1134
            log.warning("Checker for %(name)s crashed?", vars(self))
1120
1135
        return False
1121
1136
 
1122
1137
    def checked_ok(self):
1141
1156
    def need_approval(self):
1142
1157
        self.last_approval_request = datetime.datetime.utcnow()
1143
1158
 
1144
 
    def start_checker(self):
 
1159
    def start_checker(self, start_was_randomized=False):
1145
1160
        """Start a new checker subprocess if one is not running.
1146
1161
 
1147
1162
        If a checker already exists, leave it running and do
1156
1171
        # should be.
1157
1172
 
1158
1173
        if self.checker is not None and not self.checker.is_alive():
1159
 
            logger.warning("Checker was not alive; joining")
 
1174
            log.warning("Checker was not alive; joining")
1160
1175
            self.checker.join()
1161
1176
            self.checker = None
1162
1177
        # Start a new checker if needed
1168
1183
            try:
1169
1184
                command = self.checker_command % escaped_attrs
1170
1185
            except TypeError as error:
1171
 
                logger.error('Could not format string "%s"',
1172
 
                             self.checker_command,
1173
 
                             exc_info=error)
 
1186
                log.error('Could not format string "%s"',
 
1187
                          self.checker_command, exc_info=error)
1174
1188
                return True     # Try again later
1175
1189
            self.current_checker_command = command
1176
 
            logger.info("Starting checker %r for %s", command,
1177
 
                        self.name)
 
1190
            log.info("Starting checker %r for %s", command, self.name)
1178
1191
            # We don't need to redirect stdout and stderr, since
1179
1192
            # in normal mode, that is already done by daemon(),
1180
1193
            # and in debug mode we don't want to.  (Stdin is
1199
1212
                GLib.IOChannel.unix_new(pipe[0].fileno()),
1200
1213
                GLib.PRIORITY_DEFAULT, GLib.IO_IN,
1201
1214
                self.checker_callback, pipe[0], command)
 
1215
        if start_was_randomized:
 
1216
            # We were started after a random delay; Schedule a new
 
1217
            # checker to be started an 'interval' from now, and every
 
1218
            # interval from then on.
 
1219
            now = datetime.datetime.utcnow()
 
1220
            self.checker_initiator_tag = GLib.timeout_add(
 
1221
                int(self.interval.total_seconds() * 1000),
 
1222
                self.start_checker)
 
1223
            self.expires = max(self.expires, now + self.interval)
 
1224
            # Don't start a new checker again after same random delay
 
1225
            return False
1202
1226
        # Re-run this periodically if run by GLib.timeout_add
1203
1227
        return True
1204
1228
 
1209
1233
            self.checker_callback_tag = None
1210
1234
        if getattr(self, "checker", None) is None:
1211
1235
            return
1212
 
        logger.debug("Stopping checker for %(name)s", vars(self))
 
1236
        log.debug("Stopping checker for %(name)s", vars(self))
1213
1237
        self.checker.terminate()
1214
1238
        self.checker = None
1215
1239
 
1393
1417
            document.unlink()
1394
1418
        except (AttributeError, xml.dom.DOMException,
1395
1419
                xml.parsers.expat.ExpatError) as error:
1396
 
            logger.error("Failed to override Introspection method",
1397
 
                         exc_info=error)
 
1420
            log.error("Failed to override Introspection method",
 
1421
                      exc_info=error)
1398
1422
        return xmlstring
1399
1423
 
1400
1424
 
1560
1584
            document.unlink()
1561
1585
        except (AttributeError, xml.dom.DOMException,
1562
1586
                xml.parsers.expat.ExpatError) as error:
1563
 
            logger.error("Failed to override Introspection method",
1564
 
                         exc_info=error)
 
1587
            log.error("Failed to override Introspection method",
 
1588
                      exc_info=error)
1565
1589
        return xmlstring
1566
1590
 
1567
1591
 
1631
1655
            document.unlink()
1632
1656
        except (AttributeError, xml.dom.DOMException,
1633
1657
                xml.parsers.expat.ExpatError) as error:
1634
 
            logger.error("Failed to override Introspection method",
1635
 
                         exc_info=error)
 
1658
            log.error("Failed to override Introspection method",
 
1659
                      exc_info=error)
1636
1660
        return xmlstring
1637
1661
 
1638
1662
 
2305
2329
 
2306
2330
    def handle(self):
2307
2331
        with contextlib.closing(self.server.child_pipe) as child_pipe:
2308
 
            logger.info("TCP connection from: %s",
2309
 
                        str(self.client_address))
2310
 
            logger.debug("Pipe FD: %d",
2311
 
                         self.server.child_pipe.fileno())
 
2332
            log.info("TCP connection from: %s",
 
2333
                     str(self.client_address))
 
2334
            log.debug("Pipe FD: %d", self.server.child_pipe.fileno())
2312
2335
 
2313
2336
            session = gnutls.ClientSession(self.request)
2314
2337
 
2326
2349
            # Start communication using the Mandos protocol
2327
2350
            # Get protocol number
2328
2351
            line = self.request.makefile().readline()
2329
 
            logger.debug("Protocol version: %r", line)
 
2352
            log.debug("Protocol version: %r", line)
2330
2353
            try:
2331
2354
                if int(line.strip().split()[0]) > 1:
2332
2355
                    raise RuntimeError(line)
2333
2356
            except (ValueError, IndexError, RuntimeError) as error:
2334
 
                logger.error("Unknown protocol version: %s", error)
 
2357
                log.error("Unknown protocol version: %s", error)
2335
2358
                return
2336
2359
 
2337
2360
            # Start GnuTLS connection
2338
2361
            try:
2339
2362
                session.handshake()
2340
2363
            except gnutls.Error as error:
2341
 
                logger.warning("Handshake failed: %s", error)
 
2364
                log.warning("Handshake failed: %s", error)
2342
2365
                # Do not run session.bye() here: the session is not
2343
2366
                # established.  Just abandon the request.
2344
2367
                return
2345
 
            logger.debug("Handshake succeeded")
 
2368
            log.debug("Handshake succeeded")
2346
2369
 
2347
2370
            approval_required = False
2348
2371
            try:
2352
2375
                        key_id = self.key_id(
2353
2376
                            self.peer_certificate(session))
2354
2377
                    except (TypeError, gnutls.Error) as error:
2355
 
                        logger.warning("Bad certificate: %s", error)
 
2378
                        log.warning("Bad certificate: %s", error)
2356
2379
                        return
2357
 
                    logger.debug("Key ID: %s",
2358
 
                                 key_id.decode("utf-8",
2359
 
                                               errors="replace"))
 
2380
                    log.debug("Key ID: %s",
 
2381
                              key_id.decode("utf-8",
 
2382
                                            errors="replace"))
2360
2383
 
2361
2384
                else:
2362
2385
                    key_id = b""
2364
2387
                        fpr = self.fingerprint(
2365
2388
                            self.peer_certificate(session))
2366
2389
                    except (TypeError, gnutls.Error) as error:
2367
 
                        logger.warning("Bad certificate: %s", error)
 
2390
                        log.warning("Bad certificate: %s", error)
2368
2391
                        return
2369
 
                    logger.debug("Fingerprint: %s", fpr)
 
2392
                    log.debug("Fingerprint: %s", fpr)
2370
2393
 
2371
2394
                try:
2372
2395
                    client = ProxyClient(child_pipe, key_id, fpr,
2381
2404
 
2382
2405
                while True:
2383
2406
                    if not client.enabled:
2384
 
                        logger.info("Client %s is disabled",
2385
 
                                    client.name)
 
2407
                        log.info("Client %s is disabled", client.name)
2386
2408
                        if self.server.use_dbus:
2387
2409
                            # Emit D-Bus signal
2388
2410
                            client.Rejected("Disabled")
2392
2414
                        # We are approved or approval is disabled
2393
2415
                        break
2394
2416
                    elif client.approved is None:
2395
 
                        logger.info("Client %s needs approval",
2396
 
                                    client.name)
 
2417
                        log.info("Client %s needs approval",
 
2418
                                 client.name)
2397
2419
                        if self.server.use_dbus:
2398
2420
                            # Emit D-Bus signal
2399
2421
                            client.NeedApproval(
2400
2422
                                client.approval_delay.total_seconds()
2401
2423
                                * 1000, client.approved_by_default)
2402
2424
                    else:
2403
 
                        logger.warning("Client %s was not approved",
2404
 
                                       client.name)
 
2425
                        log.warning("Client %s was not approved",
 
2426
                                    client.name)
2405
2427
                        if self.server.use_dbus:
2406
2428
                            # Emit D-Bus signal
2407
2429
                            client.Rejected("Denied")
2415
2437
                    time2 = datetime.datetime.now()
2416
2438
                    if (time2 - time) >= delay:
2417
2439
                        if not client.approved_by_default:
2418
 
                            logger.warning("Client %s timed out while"
2419
 
                                           " waiting for approval",
2420
 
                                           client.name)
 
2440
                            log.warning("Client %s timed out while"
 
2441
                                        " waiting for approval",
 
2442
                                        client.name)
2421
2443
                            if self.server.use_dbus:
2422
2444
                                # Emit D-Bus signal
2423
2445
                                client.Rejected("Approval timed out")
2430
2452
                try:
2431
2453
                    session.send(client.secret)
2432
2454
                except gnutls.Error as error:
2433
 
                    logger.warning("gnutls send failed",
2434
 
                                   exc_info=error)
 
2455
                    log.warning("gnutls send failed", exc_info=error)
2435
2456
                    return
2436
2457
 
2437
 
                logger.info("Sending secret to %s", client.name)
 
2458
                log.info("Sending secret to %s", client.name)
2438
2459
                # bump the timeout using extended_timeout
2439
2460
                client.bump_timeout(client.extended_timeout)
2440
2461
                if self.server.use_dbus:
2447
2468
                try:
2448
2469
                    session.bye()
2449
2470
                except gnutls.Error as error:
2450
 
                    logger.warning("GnuTLS bye failed",
2451
 
                                   exc_info=error)
 
2471
                    log.warning("GnuTLS bye failed", exc_info=error)
2452
2472
 
2453
2473
    @staticmethod
2454
2474
    def peer_certificate(session):
2464
2484
            valid_cert_types = frozenset((gnutls.CRT_OPENPGP,))
2465
2485
        # If not a valid certificate type...
2466
2486
        if cert_type not in valid_cert_types:
2467
 
            logger.info("Cert type %r not in %r", cert_type,
2468
 
                        valid_cert_types)
 
2487
            log.info("Cert type %r not in %r", cert_type,
 
2488
                     valid_cert_types)
2469
2489
            # ...return invalid data
2470
2490
            return b""
2471
2491
        list_size = ctypes.c_uint(1)
2647
2667
            if SO_BINDTODEVICE is None:
2648
2668
                # Fall back to a hard-coded value which seems to be
2649
2669
                # common enough.
2650
 
                logger.warning("SO_BINDTODEVICE not found, trying 25")
 
2670
                log.warning("SO_BINDTODEVICE not found, trying 25")
2651
2671
                SO_BINDTODEVICE = 25
2652
2672
            try:
2653
2673
                self.socket.setsockopt(
2655
2675
                    (self.interface + "\0").encode("utf-8"))
2656
2676
            except socket.error as error:
2657
2677
                if error.errno == errno.EPERM:
2658
 
                    logger.error("No permission to bind to"
2659
 
                                 " interface %s", self.interface)
 
2678
                    log.error("No permission to bind to interface %s",
 
2679
                              self.interface)
2660
2680
                elif error.errno == errno.ENOPROTOOPT:
2661
 
                    logger.error("SO_BINDTODEVICE not available;"
2662
 
                                 " cannot bind to interface %s",
2663
 
                                 self.interface)
 
2681
                    log.error("SO_BINDTODEVICE not available; cannot"
 
2682
                              " bind to interface %s", self.interface)
2664
2683
                elif error.errno == errno.ENODEV:
2665
 
                    logger.error("Interface %s does not exist,"
2666
 
                                 " cannot bind", self.interface)
 
2684
                    log.error("Interface %s does not exist, cannot"
 
2685
                              " bind", self.interface)
2667
2686
                else:
2668
2687
                    raise
2669
2688
        # Only bind(2) the socket if we really need to.
2764
2783
                    client = c
2765
2784
                    break
2766
2785
            else:
2767
 
                logger.info("Client not found for key ID: %s, address"
2768
 
                            ": %s", key_id or fpr, address)
 
2786
                log.info("Client not found for key ID: %s, address:"
 
2787
                         " %s", key_id or fpr, address)
2769
2788
                if self.use_dbus:
2770
2789
                    # Emit D-Bus signal
2771
2790
                    mandos_dbus_service.ClientNotFound(key_id or fpr,
3165
3184
        try:
3166
3185
            pidfile = codecs.open(pidfilename, "w", encoding="utf-8")
3167
3186
        except IOError as e:
3168
 
            logger.error("Could not open file %r", pidfilename,
3169
 
                         exc_info=e)
 
3187
            log.error("Could not open file %r", pidfilename,
 
3188
                      exc_info=e)
3170
3189
 
3171
3190
    for name, group in (("_mandos", "_mandos"),
3172
3191
                        ("mandos", "mandos"),
3183
3202
    try:
3184
3203
        os.setgid(gid)
3185
3204
        os.setuid(uid)
3186
 
        if debug:
3187
 
            logger.debug("Did setuid/setgid to {}:{}".format(uid,
3188
 
                                                             gid))
 
3205
        log.debug("Did setuid/setgid to %s:%s", uid, gid)
3189
3206
    except OSError as error:
3190
 
        logger.warning("Failed to setuid/setgid to {}:{}: {}"
3191
 
                       .format(uid, gid, os.strerror(error.errno)))
 
3207
        log.warning("Failed to setuid/setgid to %s:%s: %s", uid, gid,
 
3208
                    os.strerror(error.errno))
3192
3209
        if error.errno != errno.EPERM:
3193
3210
            raise
3194
3211
 
3201
3218
 
3202
3219
        @gnutls.log_func
3203
3220
        def debug_gnutls(level, string):
3204
 
            logger.debug("GnuTLS: %s",
3205
 
                         string[:-1].decode("utf-8",
3206
 
                                            errors="replace"))
 
3221
            log.debug("GnuTLS: %s",
 
3222
                      string[:-1].decode("utf-8", errors="replace"))
3207
3223
 
3208
3224
        gnutls.global_set_log_function(debug_gnutls)
3209
3225
 
3227
3243
    # From the Avahi example code
3228
3244
    DBusGMainLoop(set_as_default=True)
3229
3245
    main_loop = GLib.MainLoop()
3230
 
    bus = dbus.SystemBus()
 
3246
    if use_dbus or zeroconf:
 
3247
        bus = dbus.SystemBus()
3231
3248
    # End of Avahi example code
3232
3249
    if use_dbus:
3233
3250
        try:
3238
3255
                "se.bsnet.fukt.Mandos", bus,
3239
3256
                do_not_queue=True)
3240
3257
        except dbus.exceptions.DBusException as e:
3241
 
            logger.error("Disabling D-Bus:", exc_info=e)
 
3258
            log.error("Disabling D-Bus:", exc_info=e)
3242
3259
            use_dbus = False
3243
3260
            server_settings["use_dbus"] = False
3244
3261
            tcp_server.use_dbus = False
3329
3346
            os.remove(stored_state_path)
3330
3347
        except IOError as e:
3331
3348
            if e.errno == errno.ENOENT:
3332
 
                logger.warning("Could not load persistent state:"
3333
 
                               " {}".format(os.strerror(e.errno)))
 
3349
                log.warning("Could not load persistent state:"
 
3350
                            " %s", os.strerror(e.errno))
3334
3351
            else:
3335
 
                logger.critical("Could not load persistent state:",
3336
 
                                exc_info=e)
 
3352
                log.critical("Could not load persistent state:",
 
3353
                             exc_info=e)
3337
3354
                raise
3338
3355
        except EOFError as e:
3339
 
            logger.warning("Could not load persistent state: "
3340
 
                           "EOFError:",
3341
 
                           exc_info=e)
 
3356
            log.warning("Could not load persistent state: EOFError:",
 
3357
                        exc_info=e)
3342
3358
 
3343
3359
    with PGPEngine() as pgp:
3344
3360
        for client_name, client in clients_data.items():
3371
3387
            if client["enabled"]:
3372
3388
                if datetime.datetime.utcnow() >= client["expires"]:
3373
3389
                    if not client["last_checked_ok"]:
3374
 
                        logger.warning(
3375
 
                            "disabling client {} - Client never "
3376
 
                            "performed a successful checker".format(
3377
 
                                client_name))
 
3390
                        log.warning("disabling client %s - Client"
 
3391
                                    " never performed a successful"
 
3392
                                    " checker", client_name)
3378
3393
                        client["enabled"] = False
3379
3394
                    elif client["last_checker_status"] != 0:
3380
 
                        logger.warning(
3381
 
                            "disabling client {} - Client last"
3382
 
                            " checker failed with error code"
3383
 
                            " {}".format(
3384
 
                                client_name,
3385
 
                                client["last_checker_status"]))
 
3395
                        log.warning("disabling client %s - Client"
 
3396
                                    " last checker failed with error"
 
3397
                                    " code %s", client_name,
 
3398
                                    client["last_checker_status"])
3386
3399
                        client["enabled"] = False
3387
3400
                    else:
3388
3401
                        client["expires"] = (
3389
3402
                            datetime.datetime.utcnow()
3390
3403
                            + client["timeout"])
3391
 
                        logger.debug("Last checker succeeded,"
3392
 
                                     " keeping {} enabled".format(
3393
 
                                         client_name))
 
3404
                        log.debug("Last checker succeeded, keeping %s"
 
3405
                                  " enabled", client_name)
3394
3406
            try:
3395
3407
                client["secret"] = pgp.decrypt(
3396
3408
                    client["encrypted_secret"],
3397
3409
                    client_settings[client_name]["secret"])
3398
3410
            except PGPError:
3399
3411
                # If decryption fails, we use secret from new settings
3400
 
                logger.debug("Failed to decrypt {} old secret".format(
3401
 
                    client_name))
 
3412
                log.debug("Failed to decrypt %s old secret",
 
3413
                          client_name)
3402
3414
                client["secret"] = (client_settings[client_name]
3403
3415
                                    ["secret"])
3404
3416
 
3418
3430
            server_settings=server_settings)
3419
3431
 
3420
3432
    if not tcp_server.clients:
3421
 
        logger.warning("No clients defined")
 
3433
        log.warning("No clients defined")
3422
3434
 
3423
3435
    if not foreground:
3424
3436
        if pidfile is not None:
3427
3439
                with pidfile:
3428
3440
                    print(pid, file=pidfile)
3429
3441
            except IOError:
3430
 
                logger.error("Could not write to file %r with PID %d",
3431
 
                             pidfilename, pid)
 
3442
                log.error("Could not write to file %r with PID %d",
 
3443
                          pidfilename, pid)
3432
3444
        del pidfile
3433
3445
        del pidfilename
3434
3446
 
3600
3612
                except NameError:
3601
3613
                    pass
3602
3614
            if e.errno in (errno.ENOENT, errno.EACCES, errno.EEXIST):
3603
 
                logger.warning("Could not save persistent state: {}"
3604
 
                               .format(os.strerror(e.errno)))
 
3615
                log.warning("Could not save persistent state: %s",
 
3616
                            os.strerror(e.errno))
3605
3617
            else:
3606
 
                logger.warning("Could not save persistent state:",
3607
 
                               exc_info=e)
 
3618
                log.warning("Could not save persistent state:",
 
3619
                            exc_info=e)
3608
3620
                raise
3609
3621
 
3610
3622
        # Delete all clients, and settings from config
3627
3639
            mandos_dbus_service.client_added_signal(client)
3628
3640
        # Need to initiate checking of clients
3629
3641
        if client.enabled:
3630
 
            client.init_checker()
 
3642
            client.init_checker(randomize_start=True)
3631
3643
 
3632
3644
    tcp_server.enable()
3633
3645
    tcp_server.server_activate()
3636
3648
    if zeroconf:
3637
3649
        service.port = tcp_server.socket.getsockname()[1]
3638
3650
    if use_ipv6:
3639
 
        logger.info("Now listening on address %r, port %d,"
3640
 
                    " flowinfo %d, scope_id %d",
3641
 
                    *tcp_server.socket.getsockname())
 
3651
        log.info("Now listening on address %r, port %d, flowinfo %d,"
 
3652
                 " scope_id %d", *tcp_server.socket.getsockname())
3642
3653
    else:                       # IPv4
3643
 
        logger.info("Now listening on address %r, port %d",
3644
 
                    *tcp_server.socket.getsockname())
 
3654
        log.info("Now listening on address %r, port %d",
 
3655
                 *tcp_server.socket.getsockname())
3645
3656
 
3646
3657
    # service.interface = tcp_server.socket.getsockname()[3]
3647
3658
 
3651
3662
            try:
3652
3663
                service.activate()
3653
3664
            except dbus.exceptions.DBusException as error:
3654
 
                logger.critical("D-Bus Exception", exc_info=error)
 
3665
                log.critical("D-Bus Exception", exc_info=error)
3655
3666
                cleanup()
3656
3667
                sys.exit(1)
3657
3668
            # End of Avahi example code
3662
3673
            lambda *args, **kwargs: (tcp_server.handle_request
3663
3674
                                     (*args[2:], **kwargs) or True))
3664
3675
 
3665
 
        logger.debug("Starting main loop")
 
3676
        log.debug("Starting main loop")
3666
3677
        main_loop.run()
3667
3678
    except AvahiError as error:
3668
 
        logger.critical("Avahi Error", exc_info=error)
 
3679
        log.critical("Avahi Error", exc_info=error)
3669
3680
        cleanup()
3670
3681
        sys.exit(1)
3671
3682
    except KeyboardInterrupt:
3672
3683
        if debug:
3673
3684
            print("", file=sys.stderr)
3674
 
        logger.debug("Server received KeyboardInterrupt")
3675
 
    logger.debug("Server exiting")
 
3685
        log.debug("Server received KeyboardInterrupt")
 
3686
    log.debug("Server exiting")
3676
3687
    # Must run before the D-Bus bus name gets deregistered
3677
3688
    cleanup()
3678
3689
 
3679
3690
 
3680
 
def should_only_run_tests():
 
3691
def parse_test_args():
 
3692
    # type: () -> argparse.Namespace
3681
3693
    parser = argparse.ArgumentParser(add_help=False)
3682
3694
    parser.add_argument("--check", action="store_true")
 
3695
    parser.add_argument("--prefix", )
3683
3696
    args, unknown_args = parser.parse_known_args()
3684
 
    run_tests = args.check
3685
 
    if run_tests:
3686
 
        # Remove --check argument from sys.argv
 
3697
    if args.check:
 
3698
        # Remove test options from sys.argv
3687
3699
        sys.argv[1:] = unknown_args
3688
 
    return run_tests
 
3700
    return args
3689
3701
 
3690
3702
# Add all tests from doctest strings
3691
3703
def load_tests(loader, tests, none):
3694
3706
    return tests
3695
3707
 
3696
3708
if __name__ == "__main__":
 
3709
    options = parse_test_args()
3697
3710
    try:
3698
 
        if should_only_run_tests():
3699
 
            # Call using ./mandos --check [--verbose]
3700
 
            unittest.main()
 
3711
        if options.check:
 
3712
            extra_test_prefix = options.prefix
 
3713
            if extra_test_prefix is not None:
 
3714
                if not (unittest.main(argv=[""], exit=False)
 
3715
                        .result.wasSuccessful()):
 
3716
                    sys.exit(1)
 
3717
                class ExtraTestLoader(unittest.TestLoader):
 
3718
                    testMethodPrefix = extra_test_prefix
 
3719
                # Call using ./scriptname --test [--verbose]
 
3720
                unittest.main(argv=[""], testLoader=ExtraTestLoader())
 
3721
            else:
 
3722
                unittest.main(argv=[""])
3701
3723
        else:
3702
3724
            main()
3703
3725
    finally:
3704
3726
        logging.shutdown()
 
3727
 
 
3728
# Local Variables:
 
3729
# run-tests:
 
3730
# (lambda (&optional extra)
 
3731
#   (if (not (funcall run-tests-in-test-buffer default-directory
 
3732
#             extra))
 
3733
#       (funcall show-test-buffer-in-test-window)
 
3734
#     (funcall remove-test-window)
 
3735
#     (if extra (message "Extra tests run successfully!"))))
 
3736
# run-tests-in-test-buffer:
 
3737
# (lambda (dir &optional extra)
 
3738
#   (with-current-buffer (get-buffer-create "*Test*")
 
3739
#     (setq buffer-read-only nil
 
3740
#           default-directory dir)
 
3741
#     (erase-buffer)
 
3742
#     (compilation-mode))
 
3743
#   (let ((process-result
 
3744
#          (let ((inhibit-read-only t))
 
3745
#            (process-file-shell-command
 
3746
#             (funcall get-command-line extra) nil "*Test*"))))
 
3747
#     (and (numberp process-result)
 
3748
#          (= process-result 0))))
 
3749
# get-command-line:
 
3750
# (lambda (&optional extra)
 
3751
#   (let ((quoted-script
 
3752
#          (shell-quote-argument (funcall get-script-name))))
 
3753
#     (format
 
3754
#      (concat "%s --check" (if extra " --prefix=atest" ""))
 
3755
#      quoted-script)))
 
3756
# get-script-name:
 
3757
# (lambda ()
 
3758
#   (if (fboundp 'file-local-name)
 
3759
#       (file-local-name (buffer-file-name))
 
3760
#     (or (file-remote-p (buffer-file-name) 'localname)
 
3761
#         (buffer-file-name))))
 
3762
# remove-test-window:
 
3763
# (lambda ()
 
3764
#   (let ((test-window (get-buffer-window "*Test*")))
 
3765
#     (if test-window (delete-window test-window))))
 
3766
# show-test-buffer-in-test-window:
 
3767
# (lambda ()
 
3768
#   (when (not (get-buffer-window-list "*Test*"))
 
3769
#     (setq next-error-last-buffer (get-buffer "*Test*"))
 
3770
#     (let* ((side (if (>= (window-width) 146) 'right 'bottom))
 
3771
#            (display-buffer-overriding-action
 
3772
#             `((display-buffer-in-side-window) (side . ,side)
 
3773
#               (window-height . fit-window-to-buffer)
 
3774
#               (window-width . fit-window-to-buffer))))
 
3775
#       (display-buffer "*Test*"))))
 
3776
# eval:
 
3777
# (progn
 
3778
#   (let* ((run-extra-tests (lambda () (interactive)
 
3779
#                             (funcall run-tests t)))
 
3780
#          (inner-keymap `(keymap (116 . ,run-extra-tests))) ; t
 
3781
#          (outer-keymap `(keymap (3 . ,inner-keymap))))     ; C-c
 
3782
#     (setq minor-mode-overriding-map-alist
 
3783
#           (cons `(run-tests . ,outer-keymap)
 
3784
#                 minor-mode-overriding-map-alist)))
 
3785
#   (add-hook 'after-save-hook run-tests 90 t))
 
3786
# End: