def test__logs_to_server_log(self):
self.patch(tftp_module, "send_node_event_ip_address")
ip = factory.make_ip_address()
self.patch(tftp_module.tftp,
'get_remote_address').return_value = (ip, sentinel.port)
clock = Clock()
file_name = factory.make_name("file")
with TwistedLoggerFixture() as logger:
log_request(file_name, clock)
clock.advance(0.0) # Don't leave anything in the reactor.
self.assertThat(logger.output,
Equals("%s requested by %s" % (file_name, ip)))
def test_monitorServices_does_not_do_anything_in_dev_environment(self):
# Belt-n-braces make sure we're in a development environment.
self.assertTrue(service_monitor_service.is_dev_environment())
monitor_service = ServiceMonitorService(Clock())
mock_ensureServices = self.patch(service_monitor, "ensureServices")
with TwistedLoggerFixture() as logger:
monitor_service.monitorServices()
self.assertThat(mock_ensureServices, MockNotCalled())
self.assertDocTestMatches(
"Skipping check of services; they're not running under the "
"supervision of systemd.", logger.output)
def test__handles_terminated_process_exit(self):
# During service stop the spawned process can be terminated with a
# signal. This is logged with a slightly different error message.
service = SleepProcessProtocolService()
with TwistedLoggerFixture() as logger:
service.startService()
yield service.stopService()
self.assertThat(
logger.output,
Equals("SleepProcessProtocolService started.\n"
"---\n"
"SleepProcessProtocolService was terminated."))
def test_tryConnection_logs_success(self):
listener = PostgresListenerService()
with TwistedLoggerFixture() as logger:
yield listener.tryConnection()
try:
self.assertThat(
logger.output,
Equals("Listening for database notifications."),
)
finally:
yield listener.stopService()
def test_loseConnection_writes_to_log(self):
protocol, factory = self.make_protocol()
status = random.randint(1000, 1010)
reason = maas_factory.make_name("reason")
with TwistedLoggerFixture() as logger:
protocol.loseConnection(status, reason)
self.assertThat(
logger.messages,
Equals([
"Closing connection: %(status)r (%(reason)r)" %
dict(status=status, reason=reason),
]))
def test_run_handles_refresh_failure(self):
clock = Clock()
service = ActiveDiscoveryService(clock)
refreshDiscoveryConfig = self.patch(service, "refreshDiscoveryConfig")
refreshDiscoveryConfig.side_effect = Exception
with TwistedLoggerFixture() as logger:
service.startService()
self.assertThat(
logger.output, DocTestMatches(dedent("""\
...: error refreshing discovery configuration.
Traceback (most recent call last):
...""")))
def test_scanIfNeeded_logs_success(self):
service = ActiveDiscoveryService(Clock())
try_lock_and_scan = self.patch(service, "try_lock_and_scan")
try_lock_and_scan.return_value = "happy"
service.discovery_enabled = True
service.discovery_last_scan = 0
service.discovery_interval = 1
service.startService()
with TwistedLoggerFixture() as logger:
yield service.run()
self.assertThat(logger.output,
DocTestMatches("...Active network discovery: happy"))
def test_is_silent_and_does_nothing_when_region_is_not_available(self):
# Patch the logger in the clusterservice so no log messages are printed
# because the tests run in debug mode.
self.patch(common.log, 'debug')
self.useFixture(MAASRootFixture())
service = dns.RackDNSService(StubClusterClientService(), reactor)
self.patch_autospec(service, "_maybeApplyConfiguration")
with TwistedLoggerFixture() as logger:
yield service._tryUpdate()
self.assertThat(logger.output, Equals(""))
self.assertThat(service._maybeApplyConfiguration, MockNotCalled())
def setUp(self):
# Every test gets a pristine MAAS_ROOT, when it is defined.
if "MAAS_ROOT" in os.environ:
self.useFixture(MAASRootFixture())
# Capture Twisted logs and add them as a test detail.
twistedLog = self.useFixture(TwistedLoggerFixture())
self.addDetail("Twisted logs", twistedLog.getContent())
self.maybeCloseDatabaseConnections()
super(MAASTestCase, self).setUp()
self.setUpResources()
self.addCleanup(self.tearDownResources)
def test_logs_errors(self):
service = self.makeService()
with TwistedLoggerFixture() as logger:
error_message = factory.make_string()
get_interfaces = self.patch(services,
"get_all_interfaces_definition")
get_interfaces.side_effect = Exception(error_message)
yield service.updateInterfaces()
self.assertThat(
logger.output,
DocTestMatches(
"Failed to update and/or record network interface configuration"
"..."))
def test_skips_and_logs_parameters_with_no_netplan_equivalent(self):
with TwistedLoggerFixture() as logger:
netplan_params = get_netplan_bridge_parameters({
"bridge_waitport": True,
"bridge_maxage": 10
})
self.assertThat(
logger.output,
DocTestMatches(
dedent("""\
...no netplan equivalent for bridge option...""")),
)
self.expectThat(netplan_params, Equals({"max-age": 10}))
def test_logs_error_when_running_region_controller_cannot_be_found(self):
service = RegionNetworksMonitoringService(reactor)
with TwistedLoggerFixture() as logger:
service.startService()
yield service.stopService()
self.assertThat(
logger.output,
DocTestMatches(
"...Failed to update and/or record network interface "
"configuration: RegionController matching query does not exist..."
))
def test_close(self):
"""
When a C{CLOSE} frame is received, the protocol closes the connection
and logs a message.
"""
with TwistedLoggerFixture() as logger:
self.protocol.dataReceived(
_makeFrame(b"", CONTROLS.CLOSE, True, mask=b"abcd")
)
self.assertFalse(self.transport.connected)
self.assertEqual(
["Closing connection: <STATUSES=NONE>"], logger.messages
)
def test__handles_normal_process_exit(self):
# If the spawned process exits with an exit code of zero this is
# logged as "ended normally".
service = TrueProcessProtocolService()
with TwistedLoggerFixture() as logger:
service.startService()
yield service._protocol.done
yield service.stopService()
self.assertThat(
logger.output,
Equals("TrueProcessProtocolService started.\n"
"---\n"
"TrueProcessProtocolService ended normally."))
def test_logs_error_when_running_region_controller_cannot_be_found(self):
service = RegionNetworksMonitoringService(reactor,
enable_beaconing=False)
with TwistedLoggerFixture() as logger:
service.startService()
yield service.stopService()
self.assertIn(
"Failed to update and/or record network interface configuration: "
"RegionController matching query does not exist",
logger.output,
)
def test_monitorServices_handles_failure(self):
# Pretend we're in a production environment.
self.patch(sms, "is_dev_environment").return_value = False
monitor_service = sms.ServiceMonitorService(
sentinel.client_service, Clock())
mock_ensureServices = self.patch(service_monitor, "ensureServices")
mock_ensureServices.return_value = fail(factory.make_exception())
with TwistedLoggerFixture() as logger:
monitor_service.monitorServices()
self.assertDocTestMatches("""\
Failed to monitor services and update region.
Traceback (most recent call last):
...""", logger.output)
def test_set_current_entry_creates_new_with_log(self):
region = factory.make_RegionController()
hostname = factory.make_hostname()
ip = factory.make_ip_address()
with TwistedLoggerFixture() as logger:
RDNS.objects.set_current_entry(ip, [hostname], region)
result = RDNS.objects.first()
self.assertThat(result.ip, Equals(ip))
self.assertThat(result.hostname, Equals(hostname))
self.assertThat(result.hostnames, Equals([hostname]))
self.assertThat(
logger.output,
DocTestMatches("New reverse DNS entry...resolves to..."),
)
def test__run_will_not_error_instead_it_logs(self):
call = self.patch(RackControllersImporter, "__call__")
call.return_value = fail(ZeroDivisionError())
with TwistedLoggerFixture() as logger:
RackControllersImporter([], []).run().wait(5)
self.assertThat(call, MockCalledOnceWith(ANY))
self.assertDocTestMatches(
"""\
General failure syncing boot resources.
Traceback (most recent call last):
...
""", logger.output)
def test__connectionLost_logs_reason(self):
listener = PostgresListenerService()
failure = Failure(factory.make_exception("Treason!"))
with TwistedLoggerFixture() as logger:
listener.connectionLost(failure)
self.assertThat(
logger.output,
DocTestMatches("""\
Connection lost.
Traceback (most recent call last):...
Failure: maastesting.factory.TestException#...: Treason!
"""))
def test_skips_and_logs_unknown_parameters(self):
with TwistedLoggerFixture() as logger:
netplan_params = get_netplan_bond_parameters({
"xbond-downdelay": 100,
"bond-mode": "active-backup",
"xbond-updelay": 200,
})
self.assertThat(
logger.output,
DocTestMatches(
dedent("""\
...unknown bond option...""")),
)
self.expectThat(netplan_params, Equals({"mode": "active-backup"}))
def test_skips_and_logs_unknown_parameters(self):
with TwistedLoggerFixture() as logger:
netplan_params = get_netplan_bridge_parameters({
"xbridge_ageing": 5,
"bridge_maxage": 10,
"xbridge_stp": True
})
self.assertThat(
logger.output,
DocTestMatches(
dedent("""\
...unknown bridge option...""")),
)
self.expectThat(netplan_params, Equals({"max-age": 10}))
def test_skips_and_logs_parameters_with_no_netplan_equivalent(self):
with TwistedLoggerFixture() as logger:
netplan_params = get_netplan_bond_parameters({
"bond-queue-id":
100,
"bond-mode":
"active-backup"
})
self.assertThat(
logger.output,
DocTestMatches(
dedent("""\
...no netplan equivalent for bond option...""")),
)
self.expectThat(netplan_params, Equals({"mode": "active-backup"}))
def test__starts_and_stops_process(self):
service = SleepProcessProtocolService()
with TwistedLoggerFixture() as logger:
service.startService()
self.assertThat(service._protocol.done, Not(IsFiredDeferred()))
yield service.stopService()
result = yield service._protocol.done
self.assertThat(result, Is(None))
self.assertThat(
logger.output,
DocTestMatches("SleepProcessProtocolService started.\n"
"-...-\n"
"SleepProcessProtocolService ..."))
with ExpectedException(ProcessExitedAlready):
service._process.signalProcess("INT")
def test_is_silent_and_does_nothing_when_rack_is_not_recognised(self):
# Patch the logger in the clusterservice so no log messages are printed
# because the tests run in debug mode.
self.patch(common.log, 'debug')
self.useFixture(MAASRootFixture())
rpc_service, protocol = yield prepareRegion(self)
protocol.GetControllerType.side_effect = exceptions.NoSuchNode
service = ntp.RackNetworkTimeProtocolService(rpc_service, reactor)
self.patch_autospec(service, "_maybeApplyConfiguration")
with TwistedLoggerFixture() as logger:
yield service._tryUpdate()
self.assertThat(logger.output, Equals(""))
self.assertThat(service._maybeApplyConfiguration, MockNotCalled())
def test__logs_when_sending_event_errors(self):
send_event = self.patch(tftp_module, "send_node_event_ip_address")
send_event.side_effect = factory.make_exception()
clock = Clock()
log_request(sentinel.filename, clock)
self.assertThat(send_event, MockNotCalled())
with TwistedLoggerFixture() as logger:
clock.advance(0.0)
self.assertDocTestMatches(
"""\
Logging TFTP request failed.
Traceback (most recent call last):
...
maastesting.factory.TestException#...
""", logger.output)
def test__protocol_selectively_logs_stderr(self):
logger = self.useFixture(TwistedLoggerFixture())
service = MDNSResolverService(lambda _: None)
protocol = service.createProcessProtocol()
reactor.spawnProcess(protocol, b"sh", (b"sh", b"-c", b"exec cat >&2"))
protocol.transport.write(b"Lines written to stderr are logged\n"
b"with a prefix, with one exception:\n"
b"Got SIGFAKE, quitting.\n")
protocol.transport.closeStdin()
yield protocol.done
self.assertThat(
logger.output,
Equals("observe-mdns: Lines written to stderr are logged\n"
"---\n"
"observe-mdns: with a prefix, with one exception:"))
def test_monitorServices_handles_scan_failure(self):
clock = Clock()
service = ActiveDiscoveryService(clock)
self.patch(service, "refreshDiscoveryConfig")
scanIfNeeded = self.patch(service, "scanIfNeeded")
scanIfNeeded.side_effect = Exception
# Pretend the call to refreshDiscoveryConfig enabled discovery,
# as expected.
service.discovery_enabled = True
with TwistedLoggerFixture() as logger:
service.run()
self.assertThat(
logger.output, DocTestMatches(dedent("""\
...: periodic scan failed.
Traceback (most recent call last):
...""")))
def test__stores_correct_values_and_fires_timer(self):
expected_last_scan = random.randint(1, 1000)
expected_interval = random.randint(1, 1000)
yield deferToDatabase(self.set_interval, expected_interval)
yield deferToDatabase(self.set_last_scan, expected_last_scan)
service = ActiveDiscoveryService(Clock())
run = self.patch(service, "run")
with TwistedLoggerFixture() as logger:
yield service.refreshDiscoveryConfig()
self.assertThat(logger.output,
DocTestMatches("...Discovery interval set to..."))
self.assertThat(service.discovery_enabled, Equals(True))
self.assertThat(service.discovery_interval, Equals(expected_interval))
self.assertThat(service.discovery_last_scan,
Equals(expected_last_scan))
self.assertThat(run, MockCalledOnceWith())
def test__protocol_logs_stderr(self):
logger = self.useFixture(TwistedLoggerFixture())
ifname = factory.make_name('eth')
service = BeaconingService(ifname, lambda _: None)
protocol = service.createProcessProtocol()
reactor.spawnProcess(protocol, b"sh", (b"sh", b"-c", b"exec cat >&2"))
protocol.transport.write(b"Lines written to stderr are logged\n"
b"with a prefix, with no exceptions.\n")
protocol.transport.closeStdin()
yield protocol.done
self.assertThat(
logger.output,
Equals("observe-beacons[%s]: Lines written to stderr are logged\n"
"---\n"
"observe-beacons[%s]: with a prefix, with no exceptions." %
(ifname, ifname)))
def test_set_current_entry_updates_existing_hostname_with_log(self):
region = factory.make_RegionController()
hostname = factory.make_hostname()
ip = factory.make_ip_address()
# Place a random hostname in the record at first...
factory.make_RDNS(ip, factory.make_hostname(), region)
# Then expect this function replaces it.
with TwistedLoggerFixture() as logger:
RDNS.objects.set_current_entry(ip, [hostname], region)
result = RDNS.objects.first()
self.assertThat(result.ip, Equals(ip))
self.assertThat(result.hostname, Equals(hostname))
self.assertThat(
logger.output,
DocTestMatches("Reverse DNS entry updated...resolves to..."),
)
