def test_filter_expiration(self): log_content_before = self.get_event_logs() line_prefix = datetime.datetime.utcnow().strftime( "%Y-%m-%dT%H:%M:%S+00:00") with DbEventsFilter(type="NO_SPACE_ERROR", node="A"): DatabaseLogEvent(type="NO_SPACE_ERROR", regex="A").add_info_and_publish( node="A", line_number=22, line=line_prefix + " this is filtered") time.sleep(5) DatabaseLogEvent(type="NO_SPACE_ERROR", regex="A").add_info_and_publish(node="A", line_number=22, line=line_prefix + " this is filtered") time.sleep(5) line_prefix = datetime.datetime.utcnow().strftime( "%Y-%m-%dT%H:%M:%S+00:00") print(line_prefix) DatabaseLogEvent(type="NO_SPACE_ERROR", regex="A").add_info_and_publish(node="A", line_number=22, line=line_prefix + " not filtered") self.wait_for_event_log_change(log_content_before) log_content_after = self.get_event_logs() self.assertIn("not filtered", log_content_after) self.assertNotIn("this is filtered", log_content_after)
def test_filter(self): log_content_before = self.get_event_logs() enospc_line = "[99.80.124.204] [stdout] Mar 31 09:08:10 warning| [shard 8] commitlog - Exception in segment reservation: storage_io_error (Storage I/O error: 28: No space left on device)" enospc_line_2 = "2019-10-29T12:19:49+00:00 ip-172-30-0-184 !WARNING | scylla: [shard 2] storage_service - " \ "Commitlog error: std::filesystem::__cxx11::filesystem_error (error system:28, filesystem error: open failed: No space left on device [/var/lib/scylla/hints/2/172.30.0.116/HintsLog-1-36028797019122576.log])" with DbEventsFilter(type='NO_SPACE_ERROR'), \ DbEventsFilter(type='BACKTRACE', line='No space left on device'), \ DbEventsFilter(type='DATABASE_ERROR', line='No space left on device'), \ DbEventsFilter(type='FILESYSTEM_ERROR', line='No space left on device'): DatabaseLogEvent(type="NO_SPACE_ERROR", regex="B").add_info_and_publish(node="A", line_number=22, line=enospc_line) DatabaseLogEvent(type="NO_SPACE_ERROR", regex="B").add_info_and_publish(node="A", line_number=22, line=enospc_line) DatabaseLogEvent(type="FILESYSTEM_ERROR", regex="B").add_info_and_publish( node="A", line_number=22, line=enospc_line_2) DatabaseLogEvent(type="NO_SPACE_ERROR", regex="B").add_info_and_publish(node="A", line_number=22, line=enospc_line) DatabaseLogEvent(type="NO_SPACE_ERROR", regex="B").add_info_and_publish(node="A", line_number=22, line=enospc_line) log_content_after = self.get_event_logs() self.assertEqual(log_content_before, log_content_after)
def test_filter_repair(self): log_content_before = self.get_event_logs() failed_repaired_line = '2019-07-28T10:53:29+00:00 ip-10-0-167-91 !INFO | scylla.bin: [shard 0] repair - Got error in row level repair: std::runtime_error (repair id 1 is aborted on shard 0)' with DbEventsFilter(type='DATABASE_ERROR', line="repair's stream failed: streaming::stream_exception"), \ DbEventsFilter(type='RUNTIME_ERROR', line='Can not find stream_manager'), \ DbEventsFilter(type='RUNTIME_ERROR', line='is aborted'): DatabaseLogEvent(type="RUNTIME_ERROR", regex="B").add_info_and_publish( node="A", line_number=22, line=failed_repaired_line) DatabaseLogEvent(type="RUNTIME_ERROR", regex="B").add_info_and_publish( node="A", line_number=22, line=failed_repaired_line) DatabaseLogEvent(type="NO_SPACE_ERROR", regex="B").add_info_and_publish( node="B", line_number=22, line="not filtered") self.wait_for_event_log_change(log_content_before) log_content_after = self.get_event_logs() self.assertIn("not filtered", log_content_after) self.assertNotIn("repair id 1", log_content_after)
def test_severity_changer_db_log(self): """ https://github.com/scylladb/scylla-cluster-tests/issues/2115 """ # 1) lower DatabaseLogEvent to warning for 1sec log_content_before = self.get_event_log_file('warning.log') with EventsSeverityChangerFilter(event_class=DatabaseLogEvent, severity=Severity.WARNING, extra_time_to_expiration=1): DatabaseLogEvent(type="NO_SPACE_ERROR", regex="B").add_info_and_publish(node="A", line_number=22, line='critical that should be lowered') DatabaseLogEvent(type="NO_SPACE_ERROR", regex="B").add_info_and_publish(node="A", line_number=22, line='critical that should be lowered #2') log_content_after = self.wait_for_event_log_change('warning.log', log_content_before) self.assertIn('DatabaseLogEvent', log_content_after) self.assertIn('critical that should be lowered', log_content_after) self.assertIn('critical that should be lowered #2', log_content_after) # 2) one of the next DatabaseLogEvent event should expire the EventsSeverityChangerFilter # (and not crash all subscribers) log_content_before = self.get_event_log_file('error.log') for _ in range(2): time.sleep(1) DatabaseLogEvent(type="NO_SPACE_ERROR", regex="B").add_info_and_publish(node="A", line_number=22, line='critical that should be lowered #2') log_content_after = self.wait_for_event_log_change('error.log', log_content_before) self.assertIn('critical that should be lowered #2', log_content_after)
def test_scylla_log_event(self): # pylint: disable=no-self-use str(DatabaseLogEvent(type="A", regex="B")) event = DatabaseLogEvent(type="A", regex="B") event.add_info("node", line='[99.80.124.204] [stdout] Mar 31 09:08:10 warning| reactor stall 2000 ms', line_number=213) event.add_backtrace_info("0x002342340\n0x12423434") str(event)
def test_stall_severity(self): # pylint: disable=no-self-use event = DatabaseLogEvent(type="REACTOR_STALLED", regex="B") event.add_info_and_publish(node="A", line_number=22, line="[99.80.124.204] [stdout] Mar 31 09:08:10 warning| reactor stall 2000 ms") assert event.severity == Severity.NORMAL event = DatabaseLogEvent(type="REACTOR_STALLED", regex="B") event.add_info_and_publish(node="A", line_number=22, line="[99.80.124.204] [stdout] Mar 31 09:08:10 warning| reactor stall 5000 ms") assert event.severity == Severity.ERROR
def test_stall_severity(self): event = DatabaseLogEvent(type="REACTOR_STALLED", regex="B") event.add_info_and_publish(node="A", line_number=22, line="[99.80.124.204] [stdout] Mar 31 09:08:10 warning| reactor stall 2000 ms") self.assertTrue(event.severity == Severity.NORMAL) event = DatabaseLogEvent(type="REACTOR_STALLED", regex="B") event.add_info_and_publish(node="A", line_number=22, line="[99.80.124.204] [stdout] Mar 31 09:08:10 warning| reactor stall 5000 ms") self.assertTrue(event.severity == Severity.CRITICAL)
def test_filter_by_node(self): log_content_before = self.get_event_log_file('events.log') with DbEventsFilter(type="NO_SPACE_ERROR", node="A"): DatabaseLogEvent(type="NO_SPACE_ERROR", regex="B").add_info_and_publish(node="A", line_number=22, line="this is filtered") DatabaseLogEvent(type="NO_SPACE_ERROR", regex="B").add_info_and_publish(node="B", line_number=22, line="not filtered") log_content_after = self.wait_for_event_log_change('events.log', log_content_before) self.assertIn("not filtered", log_content_after) self.assertNotIn("this is filtered", log_content_after)
def test_filter(self): with DbEventsFilter(type="NO_SPACE_ERROR"), DbEventsFilter(type='BACKTRACE', line='No space left on device'): DatabaseLogEvent(type="NO_SPACE_ERROR", regex="B").add_info_and_publish(node="A", line_number=22, line="[99.80.124.204] [stdout] Mar 31 09:08:10 warning| [shard 8] commitlog - Exception in segment reservation: storage_io_error (Storage I/O error: 28: No space left on device)") DatabaseLogEvent(type="NO_SPACE_ERROR", regex="B").add_info_and_publish(node="A", line_number=22, line="[99.80.124.204] [stdout] Mar 31 09:08:10 warning| [shard 8] commitlog - Exception in segment reservation: storage_io_error (Storage I/O error: 28: No space left on device)") DatabaseLogEvent(type="NO_SPACE_ERROR", regex="B").add_info_and_publish(node="A", line_number=22, line="[99.80.124.204] [stdout] Mar 31 09:08:10 warning| [shard 8] commitlog - Exception in segment reservation: storage_io_error (Storage I/O error: 28: No space left on device)") DatabaseLogEvent(type="NO_SPACE_ERROR", regex="B").add_info_and_publish(node="A", line_number=22, line="[99.80.124.204] [stdout] Mar 31 09:08:10 warning| [shard 8] commitlog - Exception in segment reservation: storage_io_error (Storage I/O error: 28: No space left on device)")
def test_filter_upgrade(self): log_content_before = self.get_event_log_file('events.log') known_failure_line = '!ERR | scylla: [shard 3] storage_proxy - Exception when communicating with 10.142.0.56: std::runtime_error (Failed to load schema version b40e405f-462c-38f2-a90c-6f130ddbf6f3)' with DbEventsFilter(type='RUNTIME_ERROR', line='Failed to load schema'): DatabaseLogEvent(type="RUNTIME_ERROR", regex="B").add_info_and_publish(node="A", line_number=22, line=known_failure_line) DatabaseLogEvent(type="RUNTIME_ERROR", regex="B").add_info_and_publish(node="A", line_number=22, line=known_failure_line) DatabaseLogEvent(type="NO_SPACE_ERROR", regex="B").add_info_and_publish(node="B", line_number=22, line="not filtered") log_content_after = self.wait_for_event_log_change('events.log', log_content_before) self.assertIn("not filtered", log_content_after) self.assertNotIn("Exception when communicating", log_content_after)
def test_error_signal_is_stopping_test(self): # pylint: disable=no-self-use DatabaseLogEvent(regex="", severity=Severity.CRITICAL, type="None").add_info_and_publish( "node1", "A line we didn't expect", "????") time.sleep(10) raise Exception("this won't happen")
def test_failed_stall_during_filter(self): # pylint: disable=no-self-use with DbEventsFilter(type="NO_SPACE_ERROR"), \ DbEventsFilter(type='BACKTRACE', line='No space left on device'): event = DatabaseLogEvent(type="REACTOR_STALLED", regex="B") event.add_info_and_publish(node="A", line_number=22, line="[99.80.124.204] [stdout] Mar 31 09:08:10 warning| reactor stall 20") logging.info(event.severity) assert event.severity == Severity.ERROR, event.severity
def test_default_filters(self): log_content_before = self.get_event_log_file('events.log') DatabaseLogEvent(type="BACKTRACE", regex="backtrace").add_info_and_publish(node="A", line_number=22, line="Jul 01 03:37:31 ip-10-0-127-151.eu-west-1. \ compute.internal scylla[6026]:\ Rate-limit: supressed 4294967292 \ backtraces on shard 5") DatabaseLogEvent(type="BACKTRACE", regex="backtrace").add_info_and_publish(node="A", line_number=22, line="other back trace that shouldn't be filtered") log_content_after = self.wait_for_event_log_change('events.log', log_content_before) self.assertIn('other back trace', log_content_after) self.assertNotIn('supressed', log_content_after)
def test_measure_speed_of_events_processing(self): # pylint: disable=no-self-use non_guaranteed_delivery = [] for _ in range(5): start_time = time.time() for _ in range(1000): evt = DatabaseLogEvent(type="NO_SPACE_ERROR", regex="B") evt.add_info(node="B", line_number=22, line="not filtered") evt.publish(guaranteed=False) non_guaranteed_delivery.append(time.time() - start_time) guaranteed_delivery = [] for _ in range(5): start_time = time.time() for _ in range(1000): evt = DatabaseLogEvent(type="NO_SPACE_ERROR", regex="B") evt.add_info(node="B", line_number=22, line="not filtered") evt.publish(guaranteed=True) guaranteed_delivery.append(time.time() - start_time) non_guaranteed_avg = sum(non_guaranteed_delivery) / len(non_guaranteed_delivery) guaranteed_avg = sum(guaranteed_delivery) / len(guaranteed_delivery) print( f"Rate of publishing 1000 events in guaranteed mode vs non guaranteed mode is {guaranteed_avg}/{non_guaranteed_avg}={(guaranteed_avg/non_guaranteed_avg) * 100}")