/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: 2022-04-24 12:16:29 UTC
  • Revision ID: teddy@recompile.se-20220424121629-rsabsoen8cjmsscd
mandos: Update logging code to more standard idioms

* mandos-monitor: Get logger using basename instead of full command.
  Also, eliminate last uses of .format() when logging.
  (logger): Rename to "log".

Show diffs side-by-side

added added

removed removed

Lines of Context:
mandos
146
146
version = "1.8.14"
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"""
1010
1009
            self.last_enabled = None
1011
1010
            self.expires = None
1012
1011
 
1013
 
        logger.debug("Creating client %r", self.name)
1014
 
        logger.debug("  Key ID: %s", self.key_id)
1015
 
        logger.debug("  Fingerprint: %s", self.fingerprint)
 
1012
        log.debug("Creating client %r", self.name)
 
1013
        log.debug("  Key ID: %s", self.key_id)
 
1014
        log.debug("  Fingerprint: %s", self.fingerprint)
1016
1015
        self.created = settings.get("created",
1017
1016
                                    datetime.datetime.utcnow())
1018
1017
 
1057
1056
        if not getattr(self, "enabled", False):
1058
1057
            return False
1059
1058
        if not quiet:
1060
 
            logger.info("Disabling client %s", self.name)
 
1059
            log.info("Disabling client %s", self.name)
1061
1060
        if getattr(self, "disable_initiator_tag", None) is not None:
1062
1061
            GLib.source_remove(self.disable_initiator_tag)
1063
1062
            self.disable_initiator_tag = None
1107
1106
            self.last_checker_status = returncode
1108
1107
            self.last_checker_signal = None
1109
1108
            if self.last_checker_status == 0:
1110
 
                logger.info("Checker for %(name)s succeeded",
1111
 
                            vars(self))
 
1109
                log.info("Checker for %(name)s succeeded", vars(self))
1112
1110
                self.checked_ok()
1113
1111
            else:
1114
 
                logger.info("Checker for %(name)s failed", vars(self))
 
1112
                log.info("Checker for %(name)s failed", vars(self))
1115
1113
        else:
1116
1114
            self.last_checker_status = -1
1117
1115
            self.last_checker_signal = -returncode
1118
 
            logger.warning("Checker for %(name)s crashed?",
1119
 
                           vars(self))
 
1116
            log.warning("Checker for %(name)s crashed?", vars(self))
1120
1117
        return False
1121
1118
 
1122
1119
    def checked_ok(self):
1156
1153
        # should be.
1157
1154
 
1158
1155
        if self.checker is not None and not self.checker.is_alive():
1159
 
            logger.warning("Checker was not alive; joining")
 
1156
            log.warning("Checker was not alive; joining")
1160
1157
            self.checker.join()
1161
1158
            self.checker = None
1162
1159
        # Start a new checker if needed
1168
1165
            try:
1169
1166
                command = self.checker_command % escaped_attrs
1170
1167
            except TypeError as error:
1171
 
                logger.error('Could not format string "%s"',
1172
 
                             self.checker_command,
1173
 
                             exc_info=error)
 
1168
                log.error('Could not format string "%s"',
 
1169
                          self.checker_command, exc_info=error)
1174
1170
                return True     # Try again later
1175
1171
            self.current_checker_command = command
1176
 
            logger.info("Starting checker %r for %s", command,
1177
 
                        self.name)
 
1172
            log.info("Starting checker %r for %s", command, self.name)
1178
1173
            # We don't need to redirect stdout and stderr, since
1179
1174
            # in normal mode, that is already done by daemon(),
1180
1175
            # and in debug mode we don't want to.  (Stdin is
1209
1204
            self.checker_callback_tag = None
1210
1205
        if getattr(self, "checker", None) is None:
1211
1206
            return
1212
 
        logger.debug("Stopping checker for %(name)s", vars(self))
 
1207
        log.debug("Stopping checker for %(name)s", vars(self))
1213
1208
        self.checker.terminate()
1214
1209
        self.checker = None
1215
1210
 
1393
1388
            document.unlink()
1394
1389
        except (AttributeError, xml.dom.DOMException,
1395
1390
                xml.parsers.expat.ExpatError) as error:
1396
 
            logger.error("Failed to override Introspection method",
1397
 
                         exc_info=error)
 
1391
            log.error("Failed to override Introspection method",
 
1392
                      exc_info=error)
1398
1393
        return xmlstring
1399
1394
 
1400
1395
 
1560
1555
            document.unlink()
1561
1556
        except (AttributeError, xml.dom.DOMException,
1562
1557
                xml.parsers.expat.ExpatError) as error:
1563
 
            logger.error("Failed to override Introspection method",
1564
 
                         exc_info=error)
 
1558
            log.error("Failed to override Introspection method",
 
1559
                      exc_info=error)
1565
1560
        return xmlstring
1566
1561
 
1567
1562
 
1631
1626
            document.unlink()
1632
1627
        except (AttributeError, xml.dom.DOMException,
1633
1628
                xml.parsers.expat.ExpatError) as error:
1634
 
            logger.error("Failed to override Introspection method",
1635
 
                         exc_info=error)
 
1629
            log.error("Failed to override Introspection method",
 
1630
                      exc_info=error)
1636
1631
        return xmlstring
1637
1632
 
1638
1633
 
2305
2300
 
2306
2301
    def handle(self):
2307
2302
        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())
 
2303
            log.info("TCP connection from: %s",
 
2304
                     str(self.client_address))
 
2305
            log.debug("Pipe FD: %d", self.server.child_pipe.fileno())
2312
2306
 
2313
2307
            session = gnutls.ClientSession(self.request)
2314
2308
 
2326
2320
            # Start communication using the Mandos protocol
2327
2321
            # Get protocol number
2328
2322
            line = self.request.makefile().readline()
2329
 
            logger.debug("Protocol version: %r", line)
 
2323
            log.debug("Protocol version: %r", line)
2330
2324
            try:
2331
2325
                if int(line.strip().split()[0]) > 1:
2332
2326
                    raise RuntimeError(line)
2333
2327
            except (ValueError, IndexError, RuntimeError) as error:
2334
 
                logger.error("Unknown protocol version: %s", error)
 
2328
                log.error("Unknown protocol version: %s", error)
2335
2329
                return
2336
2330
 
2337
2331
            # Start GnuTLS connection
2338
2332
            try:
2339
2333
                session.handshake()
2340
2334
            except gnutls.Error as error:
2341
 
                logger.warning("Handshake failed: %s", error)
 
2335
                log.warning("Handshake failed: %s", error)
2342
2336
                # Do not run session.bye() here: the session is not
2343
2337
                # established.  Just abandon the request.
2344
2338
                return
2345
 
            logger.debug("Handshake succeeded")
 
2339
            log.debug("Handshake succeeded")
2346
2340
 
2347
2341
            approval_required = False
2348
2342
            try:
2352
2346
                        key_id = self.key_id(
2353
2347
                            self.peer_certificate(session))
2354
2348
                    except (TypeError, gnutls.Error) as error:
2355
 
                        logger.warning("Bad certificate: %s", error)
 
2349
                        log.warning("Bad certificate: %s", error)
2356
2350
                        return
2357
 
                    logger.debug("Key ID: %s",
2358
 
                                 key_id.decode("utf-8",
2359
 
                                               errors="replace"))
 
2351
                    log.debug("Key ID: %s",
 
2352
                              key_id.decode("utf-8",
 
2353
                                            errors="replace"))
2360
2354
 
2361
2355
                else:
2362
2356
                    key_id = b""
2364
2358
                        fpr = self.fingerprint(
2365
2359
                            self.peer_certificate(session))
2366
2360
                    except (TypeError, gnutls.Error) as error:
2367
 
                        logger.warning("Bad certificate: %s", error)
 
2361
                        log.warning("Bad certificate: %s", error)
2368
2362
                        return
2369
 
                    logger.debug("Fingerprint: %s", fpr)
 
2363
                    log.debug("Fingerprint: %s", fpr)
2370
2364
 
2371
2365
                try:
2372
2366
                    client = ProxyClient(child_pipe, key_id, fpr,
2381
2375
 
2382
2376
                while True:
2383
2377
                    if not client.enabled:
2384
 
                        logger.info("Client %s is disabled",
2385
 
                                    client.name)
 
2378
                        log.info("Client %s is disabled", client.name)
2386
2379
                        if self.server.use_dbus:
2387
2380
                            # Emit D-Bus signal
2388
2381
                            client.Rejected("Disabled")
2392
2385
                        # We are approved or approval is disabled
2393
2386
                        break
2394
2387
                    elif client.approved is None:
2395
 
                        logger.info("Client %s needs approval",
2396
 
                                    client.name)
 
2388
                        log.info("Client %s needs approval",
 
2389
                                 client.name)
2397
2390
                        if self.server.use_dbus:
2398
2391
                            # Emit D-Bus signal
2399
2392
                            client.NeedApproval(
2400
2393
                                client.approval_delay.total_seconds()
2401
2394
                                * 1000, client.approved_by_default)
2402
2395
                    else:
2403
 
                        logger.warning("Client %s was not approved",
2404
 
                                       client.name)
 
2396
                        log.warning("Client %s was not approved",
 
2397
                                    client.name)
2405
2398
                        if self.server.use_dbus:
2406
2399
                            # Emit D-Bus signal
2407
2400
                            client.Rejected("Denied")
2415
2408
                    time2 = datetime.datetime.now()
2416
2409
                    if (time2 - time) >= delay:
2417
2410
                        if not client.approved_by_default:
2418
 
                            logger.warning("Client %s timed out while"
2419
 
                                           " waiting for approval",
2420
 
                                           client.name)
 
2411
                            log.warning("Client %s timed out while"
 
2412
                                        " waiting for approval",
 
2413
                                        client.name)
2421
2414
                            if self.server.use_dbus:
2422
2415
                                # Emit D-Bus signal
2423
2416
                                client.Rejected("Approval timed out")
2430
2423
                try:
2431
2424
                    session.send(client.secret)
2432
2425
                except gnutls.Error as error:
2433
 
                    logger.warning("gnutls send failed",
2434
 
                                   exc_info=error)
 
2426
                    log.warning("gnutls send failed", exc_info=error)
2435
2427
                    return
2436
2428
 
2437
 
                logger.info("Sending secret to %s", client.name)
 
2429
                log.info("Sending secret to %s", client.name)
2438
2430
                # bump the timeout using extended_timeout
2439
2431
                client.bump_timeout(client.extended_timeout)
2440
2432
                if self.server.use_dbus:
2447
2439
                try:
2448
2440
                    session.bye()
2449
2441
                except gnutls.Error as error:
2450
 
                    logger.warning("GnuTLS bye failed",
2451
 
                                   exc_info=error)
 
2442
                    log.warning("GnuTLS bye failed", exc_info=error)
2452
2443
 
2453
2444
    @staticmethod
2454
2445
    def peer_certificate(session):
2464
2455
            valid_cert_types = frozenset((gnutls.CRT_OPENPGP,))
2465
2456
        # If not a valid certificate type...
2466
2457
        if cert_type not in valid_cert_types:
2467
 
            logger.info("Cert type %r not in %r", cert_type,
2468
 
                        valid_cert_types)
 
2458
            log.info("Cert type %r not in %r", cert_type,
 
2459
                     valid_cert_types)
2469
2460
            # ...return invalid data
2470
2461
            return b""
2471
2462
        list_size = ctypes.c_uint(1)
2647
2638
            if SO_BINDTODEVICE is None:
2648
2639
                # Fall back to a hard-coded value which seems to be
2649
2640
                # common enough.
2650
 
                logger.warning("SO_BINDTODEVICE not found, trying 25")
 
2641
                log.warning("SO_BINDTODEVICE not found, trying 25")
2651
2642
                SO_BINDTODEVICE = 25
2652
2643
            try:
2653
2644
                self.socket.setsockopt(
2655
2646
                    (self.interface + "\0").encode("utf-8"))
2656
2647
            except socket.error as error:
2657
2648
                if error.errno == errno.EPERM:
2658
 
                    logger.error("No permission to bind to"
2659
 
                                 " interface %s", self.interface)
 
2649
                    log.error("No permission to bind to interface %s",
 
2650
                              self.interface)
2660
2651
                elif error.errno == errno.ENOPROTOOPT:
2661
 
                    logger.error("SO_BINDTODEVICE not available;"
2662
 
                                 " cannot bind to interface %s",
2663
 
                                 self.interface)
 
2652
                    log.error("SO_BINDTODEVICE not available; cannot"
 
2653
                              " bind to interface %s", self.interface)
2664
2654
                elif error.errno == errno.ENODEV:
2665
 
                    logger.error("Interface %s does not exist,"
2666
 
                                 " cannot bind", self.interface)
 
2655
                    log.error("Interface %s does not exist, cannot"
 
2656
                              " bind", self.interface)
2667
2657
                else:
2668
2658
                    raise
2669
2659
        # Only bind(2) the socket if we really need to.
2764
2754
                    client = c
2765
2755
                    break
2766
2756
            else:
2767
 
                logger.info("Client not found for key ID: %s, address"
2768
 
                            ": %s", key_id or fpr, address)
 
2757
                log.info("Client not found for key ID: %s, address:"
 
2758
                         " %s", key_id or fpr, address)
2769
2759
                if self.use_dbus:
2770
2760
                    # Emit D-Bus signal
2771
2761
                    mandos_dbus_service.ClientNotFound(key_id or fpr,
3165
3155
        try:
3166
3156
            pidfile = codecs.open(pidfilename, "w", encoding="utf-8")
3167
3157
        except IOError as e:
3168
 
            logger.error("Could not open file %r", pidfilename,
3169
 
                         exc_info=e)
 
3158
            log.error("Could not open file %r", pidfilename,
 
3159
                      exc_info=e)
3170
3160
 
3171
3161
    for name, group in (("_mandos", "_mandos"),
3172
3162
                        ("mandos", "mandos"),
3183
3173
    try:
3184
3174
        os.setgid(gid)
3185
3175
        os.setuid(uid)
3186
 
        if debug:
3187
 
            logger.debug("Did setuid/setgid to {}:{}".format(uid,
3188
 
                                                             gid))
 
3176
        log.debug("Did setuid/setgid to %s:%s", uid, gid)
3189
3177
    except OSError as error:
3190
 
        logger.warning("Failed to setuid/setgid to {}:{}: {}"
3191
 
                       .format(uid, gid, os.strerror(error.errno)))
 
3178
        log.warning("Failed to setuid/setgid to %s:%s: %s", uid, gid,
 
3179
                    os.strerror(error.errno))
3192
3180
        if error.errno != errno.EPERM:
3193
3181
            raise
3194
3182
 
3201
3189
 
3202
3190
        @gnutls.log_func
3203
3191
        def debug_gnutls(level, string):
3204
 
            logger.debug("GnuTLS: %s",
3205
 
                         string[:-1].decode("utf-8",
3206
 
                                            errors="replace"))
 
3192
            log.debug("GnuTLS: %s",
 
3193
                      string[:-1].decode("utf-8", errors="replace"))
3207
3194
 
3208
3195
        gnutls.global_set_log_function(debug_gnutls)
3209
3196
 
3238
3225
                "se.bsnet.fukt.Mandos", bus,
3239
3226
                do_not_queue=True)
3240
3227
        except dbus.exceptions.DBusException as e:
3241
 
            logger.error("Disabling D-Bus:", exc_info=e)
 
3228
            log.error("Disabling D-Bus:", exc_info=e)
3242
3229
            use_dbus = False
3243
3230
            server_settings["use_dbus"] = False
3244
3231
            tcp_server.use_dbus = False
3329
3316
            os.remove(stored_state_path)
3330
3317
        except IOError as e:
3331
3318
            if e.errno == errno.ENOENT:
3332
 
                logger.warning("Could not load persistent state:"
3333
 
                               " {}".format(os.strerror(e.errno)))
 
3319
                log.warning("Could not load persistent state:"
 
3320
                            " %s", os.strerror(e.errno))
3334
3321
            else:
3335
 
                logger.critical("Could not load persistent state:",
3336
 
                                exc_info=e)
 
3322
                log.critical("Could not load persistent state:",
 
3323
                             exc_info=e)
3337
3324
                raise
3338
3325
        except EOFError as e:
3339
 
            logger.warning("Could not load persistent state: "
3340
 
                           "EOFError:",
3341
 
                           exc_info=e)
 
3326
            log.warning("Could not load persistent state: EOFError:",
 
3327
                        exc_info=e)
3342
3328
 
3343
3329
    with PGPEngine() as pgp:
3344
3330
        for client_name, client in clients_data.items():
3371
3357
            if client["enabled"]:
3372
3358
                if datetime.datetime.utcnow() >= client["expires"]:
3373
3359
                    if not client["last_checked_ok"]:
3374
 
                        logger.warning(
3375
 
                            "disabling client {} - Client never "
3376
 
                            "performed a successful checker".format(
3377
 
                                client_name))
 
3360
                        log.warning("disabling client %s - Client"
 
3361
                                    " never performed a successful"
 
3362
                                    " checker", client_name)
3378
3363
                        client["enabled"] = False
3379
3364
                    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"]))
 
3365
                        log.warning("disabling client %s - Client"
 
3366
                                    " last checker failed with error"
 
3367
                                    " code %s", client_name,
 
3368
                                    client["last_checker_status"])
3386
3369
                        client["enabled"] = False
3387
3370
                    else:
3388
3371
                        client["expires"] = (
3389
3372
                            datetime.datetime.utcnow()
3390
3373
                            + client["timeout"])
3391
 
                        logger.debug("Last checker succeeded,"
3392
 
                                     " keeping {} enabled".format(
3393
 
                                         client_name))
 
3374
                        log.debug("Last checker succeeded, keeping %s"
 
3375
                                  " enabled", client_name)
3394
3376
            try:
3395
3377
                client["secret"] = pgp.decrypt(
3396
3378
                    client["encrypted_secret"],
3397
3379
                    client_settings[client_name]["secret"])
3398
3380
            except PGPError:
3399
3381
                # If decryption fails, we use secret from new settings
3400
 
                logger.debug("Failed to decrypt {} old secret".format(
3401
 
                    client_name))
 
3382
                log.debug("Failed to decrypt %s old secret",
 
3383
                          client_name)
3402
3384
                client["secret"] = (client_settings[client_name]
3403
3385
                                    ["secret"])
3404
3386
 
3418
3400
            server_settings=server_settings)
3419
3401
 
3420
3402
    if not tcp_server.clients:
3421
 
        logger.warning("No clients defined")
 
3403
        log.warning("No clients defined")
3422
3404
 
3423
3405
    if not foreground:
3424
3406
        if pidfile is not None:
3427
3409
                with pidfile:
3428
3410
                    print(pid, file=pidfile)
3429
3411
            except IOError:
3430
 
                logger.error("Could not write to file %r with PID %d",
3431
 
                             pidfilename, pid)
 
3412
                log.error("Could not write to file %r with PID %d",
 
3413
                          pidfilename, pid)
3432
3414
        del pidfile
3433
3415
        del pidfilename
3434
3416
 
3600
3582
                except NameError:
3601
3583
                    pass
3602
3584
            if e.errno in (errno.ENOENT, errno.EACCES, errno.EEXIST):
3603
 
                logger.warning("Could not save persistent state: {}"
3604
 
                               .format(os.strerror(e.errno)))
 
3585
                log.warning("Could not save persistent state: %s",
 
3586
                            os.strerror(e.errno))
3605
3587
            else:
3606
 
                logger.warning("Could not save persistent state:",
3607
 
                               exc_info=e)
 
3588
                log.warning("Could not save persistent state:",
 
3589
                            exc_info=e)
3608
3590
                raise
3609
3591
 
3610
3592
        # Delete all clients, and settings from config
3636
3618
    if zeroconf:
3637
3619
        service.port = tcp_server.socket.getsockname()[1]
3638
3620
    if use_ipv6:
3639
 
        logger.info("Now listening on address %r, port %d,"
3640
 
                    " flowinfo %d, scope_id %d",
3641
 
                    *tcp_server.socket.getsockname())
 
3621
        log.info("Now listening on address %r, port %d, flowinfo %d,"
 
3622
                 " scope_id %d", *tcp_server.socket.getsockname())
3642
3623
    else:                       # IPv4
3643
 
        logger.info("Now listening on address %r, port %d",
3644
 
                    *tcp_server.socket.getsockname())
 
3624
        log.info("Now listening on address %r, port %d",
 
3625
                 *tcp_server.socket.getsockname())
3645
3626
 
3646
3627
    # service.interface = tcp_server.socket.getsockname()[3]
3647
3628
 
3651
3632
            try:
3652
3633
                service.activate()
3653
3634
            except dbus.exceptions.DBusException as error:
3654
 
                logger.critical("D-Bus Exception", exc_info=error)
 
3635
                log.critical("D-Bus Exception", exc_info=error)
3655
3636
                cleanup()
3656
3637
                sys.exit(1)
3657
3638
            # End of Avahi example code
3662
3643
            lambda *args, **kwargs: (tcp_server.handle_request
3663
3644
                                     (*args[2:], **kwargs) or True))
3664
3645
 
3665
 
        logger.debug("Starting main loop")
 
3646
        log.debug("Starting main loop")
3666
3647
        main_loop.run()
3667
3648
    except AvahiError as error:
3668
 
        logger.critical("Avahi Error", exc_info=error)
 
3649
        log.critical("Avahi Error", exc_info=error)
3669
3650
        cleanup()
3670
3651
        sys.exit(1)
3671
3652
    except KeyboardInterrupt:
3672
3653
        if debug:
3673
3654
            print("", file=sys.stderr)
3674
 
        logger.debug("Server received KeyboardInterrupt")
3675
 
    logger.debug("Server exiting")
 
3655
        log.debug("Server received KeyboardInterrupt")
 
3656
    log.debug("Server exiting")
3676
3657
    # Must run before the D-Bus bus name gets deregistered
3677
3658
    cleanup()
3678
3659