191
191
syslogger.setFormatter(logging.Formatter
192
192
("Mandos [%(process)d]: %(levelname)s:"
194
logger.addHandler(syslogger)
194
log.addHandler(syslogger)
197
197
console = logging.StreamHandler()
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.",
397
log.critical("No suitable Zeroconf service name found"
398
" after %i retries, exiting.",
400
400
raise AvahiServiceError("Too many renames")
402
402
self.server.GetAlternativeServiceName(self.name))
403
403
self.rename_count += 1
404
logger.info("Changing Zeroconf service name to %r ...",
404
log.info("Changing Zeroconf service name to %r ...",
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)
416
logger.critical("D-Bus Exception", exc_info=error)
416
log.critical("D-Bus Exception", exc_info=error)
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(
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)
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.")
460
460
elif state == avahi.ENTRY_GROUP_FAILURE:
461
logger.critical("Avahi: Error in group state changed %s",
461
log.critical("Avahi: Error in group state changed %s",
463
463
raise AvahiGroupError("State changed: {!s}".format(error))
465
465
def cleanup(self):
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)
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])
490
logger.error(bad_states[state] + ": %r", error)
490
log.error(bad_states[state] + ": %r", error)
492
492
elif state == avahi.SERVER_RUNNING:
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"
498
log.info("Local Zeroconf service name collision.")
500
499
return self.rename(remove=False)
502
logger.critical("D-Bus Exception", exc_info=error)
501
log.critical("D-Bus Exception", exc_info=error)
506
505
if error is None:
507
logger.debug("Unknown state: %r", state)
506
log.debug("Unknown state: %r", state)
509
logger.debug("Unknown state: %r: %r", state, error)
508
log.debug("Unknown state: %r: %r", state, error)
511
510
def activate(self):
512
511
"""Derived from the Avahi example code"""
1010
1009
self.last_enabled = None
1011
1010
self.expires = None
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())
1057
1056
if not getattr(self, "enabled", False):
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",
1109
log.info("Checker for %(name)s succeeded", vars(self))
1112
1110
self.checked_ok()
1114
logger.info("Checker for %(name)s failed", vars(self))
1112
log.info("Checker for %(name)s failed", vars(self))
1116
1114
self.last_checker_status = -1
1117
1115
self.last_checker_signal = -returncode
1118
logger.warning("Checker for %(name)s crashed?",
1116
log.warning("Checker for %(name)s crashed?", vars(self))
1122
1119
def checked_ok(self):
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,
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,
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:
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
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",
1391
log.error("Failed to override Introspection method",
1398
1393
return xmlstring
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",
1558
log.error("Failed to override Introspection method",
1565
1560
return xmlstring
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",
1629
log.error("Failed to override Introspection method",
1636
1631
return xmlstring
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())
2313
2307
session = gnutls.ClientSession(self.request)
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)
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)
2337
2331
# Start GnuTLS connection
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.
2345
logger.debug("Handshake succeeded")
2339
log.debug("Handshake succeeded")
2347
2341
approval_required = False
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)
2357
logger.debug("Key ID: %s",
2358
key_id.decode("utf-8",
2351
log.debug("Key ID: %s",
2352
key_id.decode("utf-8",
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)
2369
logger.debug("Fingerprint: %s", fpr)
2363
log.debug("Fingerprint: %s", fpr)
2372
2366
client = ProxyClient(child_pipe, key_id, fpr,
2392
2385
# We are approved or approval is disabled
2394
2387
elif client.approved is None:
2395
logger.info("Client %s needs approval",
2388
log.info("Client %s needs approval",
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)
2403
logger.warning("Client %s was not approved",
2396
log.warning("Client %s was not approved",
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",
2411
log.warning("Client %s timed out while"
2412
" waiting for approval",
2421
2414
if self.server.use_dbus:
2422
2415
# Emit D-Bus signal
2423
2416
client.Rejected("Approval timed out")
2431
2424
session.send(client.secret)
2432
2425
except gnutls.Error as error:
2433
logger.warning("gnutls send failed",
2426
log.warning("gnutls send failed", exc_info=error)
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:
2449
2441
except gnutls.Error as error:
2450
logger.warning("GnuTLS bye failed",
2442
log.warning("GnuTLS bye failed", exc_info=error)
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,
2458
log.info("Cert type %r not in %r", cert_type,
2469
2460
# ...return invalid data
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
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",
2660
2651
elif error.errno == errno.ENOPROTOOPT:
2661
logger.error("SO_BINDTODEVICE not available;"
2662
" cannot bind to interface %s",
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)
2669
2659
# Only bind(2) the socket if we really need to.
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,
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,
3158
log.error("Could not open file %r", pidfilename,
3171
3161
for name, group in (("_mandos", "_mandos"),
3172
3162
("mandos", "mandos"),
3187
logger.debug("Did setuid/setgid to {}:{}".format(uid,
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:
3202
3190
@gnutls.log_func
3203
3191
def debug_gnutls(level, string):
3204
logger.debug("GnuTLS: %s",
3205
string[:-1].decode("utf-8",
3192
log.debug("GnuTLS: %s",
3193
string[:-1].decode("utf-8", errors="replace"))
3208
3195
gnutls.global_set_log_function(debug_gnutls)
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))
3335
logger.critical("Could not load persistent state:",
3322
log.critical("Could not load persistent state:",
3338
3325
except EOFError as e:
3339
logger.warning("Could not load persistent state: "
3326
log.warning("Could not load persistent state: EOFError:",
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"]:
3375
"disabling client {} - Client never "
3376
"performed a successful checker".format(
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:
3381
"disabling client {} - Client last"
3382
" checker failed with error code"
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
3388
3371
client["expires"] = (
3389
3372
datetime.datetime.utcnow()
3390
3373
+ client["timeout"])
3391
logger.debug("Last checker succeeded,"
3392
" keeping {} enabled".format(
3374
log.debug("Last checker succeeded, keeping %s"
3375
" enabled", client_name)
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(
3382
log.debug("Failed to decrypt %s old secret",
3402
3384
client["secret"] = (client_settings[client_name]
3600
3582
except NameError:
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))
3606
logger.warning("Could not save persistent state:",
3588
log.warning("Could not save persistent state:",
3610
3592
# Delete all clients, and settings from config
3637
3619
service.port = tcp_server.socket.getsockname()[1]
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())
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())
3646
3627
# service.interface = tcp_server.socket.getsockname()[3]
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)
3657
3638
# End of Avahi example code
3662
3643
lambda *args, **kwargs: (tcp_server.handle_request
3663
3644
(*args[2:], **kwargs) or True))
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)
3671
3652
except KeyboardInterrupt:
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