/*
* Copyright © 2014-2016 Cask Data, Inc.
*
* Licensed under the Apache License, Version 2.0 (the "License"); you may not
* use this file except in compliance with the License. You may obtain a copy of
* the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
* WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
* License for the specific language governing permissions and limitations under
* the License.
*/
package co.cask.cdap.logging.save;
import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.util.StatusPrinter;
import co.cask.cdap.api.data.schema.Schema;
import co.cask.cdap.common.conf.CConfiguration;
import co.cask.cdap.common.conf.Constants;
import co.cask.cdap.common.logging.ApplicationLoggingContext;
import co.cask.cdap.common.logging.ComponentLoggingContext;
import co.cask.cdap.common.logging.LoggingContext;
import co.cask.cdap.common.logging.LoggingContextAccessor;
import co.cask.cdap.common.logging.NamespaceLoggingContext;
import co.cask.cdap.common.logging.ServiceLoggingContext;
import co.cask.cdap.common.logging.SystemLoggingContext;
import co.cask.cdap.data2.dataset2.lib.table.inmemory.InMemoryTableService;
import co.cask.cdap.internal.io.SchemaTypeAdapter;
import co.cask.cdap.logging.KafkaTestBase;
import co.cask.cdap.logging.LoggingConfiguration;
import co.cask.cdap.logging.appender.LogAppenderInitializer;
import co.cask.cdap.logging.appender.kafka.KafkaLogAppender;
import co.cask.cdap.logging.appender.kafka.LoggingEventSerializer;
import co.cask.cdap.logging.context.FlowletLoggingContext;
import co.cask.cdap.logging.context.LoggingContextHelper;
import co.cask.cdap.logging.filter.Filter;
import co.cask.cdap.logging.read.AvroFileReader;
import co.cask.cdap.logging.read.FileLogReader;
import co.cask.cdap.logging.read.LogEvent;
import co.cask.cdap.logging.serialize.LogSchema;
import co.cask.cdap.test.SlowTests;
import co.cask.tephra.TransactionManager;
import com.google.common.base.Function;
import com.google.common.collect.ArrayListMultimap;
import com.google.common.collect.ImmutableSet;
import com.google.common.collect.Lists;
import com.google.common.collect.Maps;
import com.google.common.collect.Multimap;
import com.google.common.util.concurrent.Futures;
import com.google.common.util.concurrent.ListenableFuture;
import com.google.common.util.concurrent.ListeningExecutorService;
import com.google.common.util.concurrent.MoreExecutors;
import com.google.gson.Gson;
import com.google.gson.GsonBuilder;
import com.google.inject.Injector;
import com.google.inject.Key;
import com.google.inject.TypeLiteral;
import com.google.inject.name.Names;
import org.apache.commons.io.FilenameUtils;
import org.apache.twill.filesystem.Location;
import org.apache.twill.filesystem.LocationFactory;
import org.apache.twill.kafka.client.FetchedMessage;
import org.junit.AfterClass;
import org.junit.Assert;
import org.junit.BeforeClass;
import org.junit.Test;
import org.junit.experimental.categories.Category;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import java.io.ByteArrayOutputStream;
import java.io.IOException;
import java.io.PrintStream;
import java.text.SimpleDateFormat;
import java.util.Collection;
import java.util.Date;
import java.util.HashMap;
import java.util.List;
import java.util.Map;
import java.util.Set;
import java.util.SortedMap;
import java.util.concurrent.Executors;
import java.util.concurrent.TimeUnit;
import static co.cask.cdap.logging.appender.LoggingTester.LogCallback;
/**
* Test LogSaver and Distributed Log Reader.
*/
@Category(SlowTests.class)
public class LogSaverTest extends KafkaTestBase {
private static final Logger LOG = LoggerFactory.getLogger(LogSaverTest.class);
private static Injector injector;
private static TransactionManager txManager;
private static String logBaseDir;
private static KafkaLogAppender appender;
private static Gson gson;
@BeforeClass
public static void startLogSaver() throws Exception {
CConfiguration cConf = KAFKA_TESTER.getCConf();
logBaseDir = cConf.get(LoggingConfiguration.LOG_BASE_DIR) + "/" + LogSaverTest.class.getSimpleName();
cConf.set(LoggingConfiguration.LOG_BASE_DIR, logBaseDir);
injector = KAFKA_TESTER.getInjector();
txManager = injector.getInstance(TransactionManager.class);
txManager.startAndWait();
appender = injector.getInstance(KafkaLogAppender.class);
CountingLogAppender countingLogAppender = new CountingLogAppender(appender);
new LogAppenderInitializer(countingLogAppender).initialize("LogSaverTest");
gson = new GsonBuilder().registerTypeAdapter(Schema.class, new SchemaTypeAdapter()).create();
LogSaverFactory factory = injector.getInstance(LogSaverFactory.class);
// {0, 1} - because we have 2 partitions as per configuration above (see LoggingConfiguration.NUM_PARTITIONS)
LogSaver logSaver = factory.create(ImmutableSet.of(0, 1));
logSaver.startAndWait();
publishLogs();
LocationFactory locationFactory = injector.getInstance(LocationFactory.class);
String logBaseDir = cConf.get(LoggingConfiguration.LOG_BASE_DIR);
String namespacesDir = cConf.get(Constants.Namespace.NAMESPACES_DIR);
Location ns1LogBaseDir = locationFactory.create(namespacesDir).append("NS_1").append(logBaseDir);
Location ns2LogBaseDir = locationFactory.create(namespacesDir).append("NS_2").append(logBaseDir);
Location systemLogBaseDir = locationFactory.create(namespacesDir).append("system").append(logBaseDir);
waitTillLogSaverDone(ns1LogBaseDir, "APP_1/flow-FLOW_1/%s", "Test log message 119 arg1 arg2");
waitTillLogSaverDone(ns2LogBaseDir, "APP_2/flow-FLOW_2/%s", "Test log message 119 arg1 arg2");
waitTillLogSaverDone(systemLogBaseDir, "services/service-metrics/%s", "Test log message 59 arg1 arg2");
logSaver.stopAndWait();
}
@AfterClass
public static void cleanUp() throws Exception {
appender.stop();
InMemoryTableService.reset();
txManager.stopAndWait();
}
@Test
public void testCheckpoint() throws Exception {
TypeLiteral<Set<KafkaLogProcessor>> type = new TypeLiteral<Set<KafkaLogProcessor>>() { };
Set<KafkaLogProcessor> processors =
injector.getInstance(Key.get(type, Names.named(Constants.LogSaver.MESSAGE_PROCESSORS)));
try {
for (KafkaLogProcessor processor : processors) {
CheckpointManager checkpointManager = getCheckPointManager(processor);
// Verify checkpoint offset
Assert.assertEquals(180, checkpointManager.getCheckpoint(0).getNextOffset());
Assert.assertEquals(120, checkpointManager.getCheckpoint(1).getNextOffset());
// Verify checkpoint time
// Read with null runid should give 120 results back
long checkpointTimeApp1 =
getCheckpointTime(new FlowletLoggingContext("NS_1", "APP_1", "FLOW_1", "", null, "INSTANCE"), 120);
long checkpointTimeApp2 =
getCheckpointTime(new FlowletLoggingContext("NS_2", "APP_2", "FLOW_2", "", null, "INSTANCE"), 120);
long checkpointTimeService = getCheckpointTime(new ServiceLoggingContext("system", "services", "metrics"), 60);
// Checkpoint time should be within last 10 minutes
long currentTime = System.currentTimeMillis();
Assert.assertTrue(checkpointTimeApp1 > currentTime - TimeUnit.MINUTES.toMillis(10));
Assert.assertTrue(checkpointTimeApp2 > currentTime - TimeUnit.MINUTES.toMillis(10));
Assert.assertTrue(checkpointTimeService > currentTime - TimeUnit.MINUTES.toMillis(10));
// Saved checkpoint must be equal to time on last message for a partition.
Assert.assertEquals(checkpointTimeApp1, checkpointManager.getCheckpoint(0).getMaxEventTime());
Assert.assertTrue(checkpointManager.getCheckpoint(1).getMaxEventTime() == checkpointTimeApp2 ||
checkpointManager.getCheckpoint(1).getMaxEventTime() == checkpointTimeService);
}
} catch (Throwable t) {
try {
final Multimap<String, String> contextMessages = getPublishedKafkaMessages();
LOG.error("All kafka messages: {}", contextMessages);
} catch (Exception e) {
LOG.error("Error while getting published kafka messages {}", e);
}
throw t;
}
}
private static CheckpointManager getCheckPointManager(KafkaLogProcessor processor) {
if (processor instanceof KafkaLogWriterPlugin) {
KafkaLogWriterPlugin plugin = (KafkaLogWriterPlugin) processor;
return plugin.getCheckPointManager();
} else if (processor instanceof LogMetricsPlugin) {
LogMetricsPlugin plugin = (LogMetricsPlugin) processor;
return plugin.getCheckPointManager();
}
throw new IllegalArgumentException("Invalid processor");
}
@Test
public void testLogRead1() throws Exception {
testLogRead(new FlowletLoggingContext("NS_1", "APP_1", "FLOW_1", "", "RUN1", "INSTANCE"));
}
@Test
public void testLogRead2() throws Exception {
testLogRead(new FlowletLoggingContext("NS_2", "APP_2", "FLOW_2", "", "RUN1", "INSTANCE"));
}
@Test
public void testLogRead3() throws Exception {
testLogRead(new ServiceLoggingContext("system", "services", "metrics"));
}
private long getCheckpointTime(LoggingContext loggingContext, int numExpectedEvents) throws Exception {
LogCallback logCallback = new LogCallback();
FileLogReader distributedLogReader = injector.getInstance(FileLogReader.class);
distributedLogReader.getLog(loggingContext, 0, Long.MAX_VALUE, Filter.EMPTY_FILTER, logCallback);
Assert.assertEquals(numExpectedEvents, logCallback.getEvents().size());
return logCallback.getEvents().get(numExpectedEvents - 1).getLoggingEvent().getTimeStamp();
}
private void testLogRead(LoggingContext loggingContext) throws Exception {
LOG.info("Verifying logging context {}", loggingContext.getLogPathFragment(logBaseDir));
FileLogReader distributedLogReader = injector.getInstance(FileLogReader.class);
LogCallback logCallback1 = new LogCallback();
distributedLogReader.getLog(loggingContext, 0, Long.MAX_VALUE, Filter.EMPTY_FILTER, logCallback1);
List<LogEvent> allEvents = logCallback1.getEvents();
final Multimap<String, String> contextMessages = getPublishedKafkaMessages();
for (int i = 0; i < 60; ++i) {
Assert.assertEquals("All messages in Kafka = " + gson.toJson(contextMessages.asMap()),
String.format("Test log message %d arg1 arg2", i),
allEvents.get(i).getLoggingEvent().getFormattedMessage());
if (loggingContext instanceof ServiceLoggingContext) {
Assert.assertEquals(
loggingContext.getSystemTagsMap().get(SystemLoggingContext.TAG_SYSTEM_ID).getValue(),
allEvents.get(i).getLoggingEvent().getMDCPropertyMap().get(SystemLoggingContext.TAG_SYSTEM_ID));
Assert.assertEquals(
loggingContext.getSystemTagsMap().get(ComponentLoggingContext.TAG_COMPONENT_ID).getValue(),
allEvents.get(i).getLoggingEvent().getMDCPropertyMap().get(ComponentLoggingContext.TAG_COMPONENT_ID));
Assert.assertEquals(
loggingContext.getSystemTagsMap().get(ServiceLoggingContext.TAG_SERVICE_ID).getValue(),
allEvents.get(i).getLoggingEvent().getMDCPropertyMap().get(ServiceLoggingContext.TAG_SERVICE_ID));
} else {
Assert.assertEquals(
loggingContext.getSystemTagsMap().get(NamespaceLoggingContext.TAG_NAMESPACE_ID).getValue(),
allEvents.get(i).getLoggingEvent().getMDCPropertyMap().get(NamespaceLoggingContext.TAG_NAMESPACE_ID));
Assert.assertEquals(
loggingContext.getSystemTagsMap().get(ApplicationLoggingContext.TAG_APPLICATION_ID).getValue(),
allEvents.get(i).getLoggingEvent().getMDCPropertyMap().get(ApplicationLoggingContext.TAG_APPLICATION_ID));
Assert.assertEquals(
loggingContext.getSystemTagsMap().get(FlowletLoggingContext.TAG_FLOW_ID).getValue(),
allEvents.get(i).getLoggingEvent().getMDCPropertyMap().get(FlowletLoggingContext.TAG_FLOW_ID));
}
}
LogCallback logCallback2 = new LogCallback();
distributedLogReader.getLog(loggingContext, allEvents.get(10).getLoggingEvent().getTimeStamp(),
allEvents.get(20).getLoggingEvent().getTimeStamp(), Filter.EMPTY_FILTER, logCallback2);
List<LogEvent> events = logCallback2.getEvents();
Assert.assertEquals(10, events.size());
Assert.assertEquals("Test log message 10 arg1 arg2", events.get(0).getLoggingEvent().getFormattedMessage());
Assert.assertEquals("Test log message 19 arg1 arg2", events.get(9).getLoggingEvent().getFormattedMessage());
LogCallback logCallback3 = new LogCallback();
distributedLogReader.getLog(loggingContext, allEvents.get(5).getLoggingEvent().getTimeStamp(),
allEvents.get(55).getLoggingEvent().getTimeStamp(), Filter.EMPTY_FILTER, logCallback3);
events = logCallback3.getEvents();
Assert.assertEquals(50, events.size());
Assert.assertEquals("Test log message 5 arg1 arg2", events.get(0).getLoggingEvent().getFormattedMessage());
Assert.assertEquals("Test log message 54 arg1 arg2", events.get(49).getLoggingEvent().getFormattedMessage());
LogCallback logCallback4 = new LogCallback();
distributedLogReader.getLog(loggingContext, allEvents.get(30).getLoggingEvent().getTimeStamp(),
allEvents.get(53).getLoggingEvent().getTimeStamp(), Filter.EMPTY_FILTER, logCallback4);
events = logCallback4.getEvents();
Assert.assertEquals(23, events.size());
Assert.assertEquals("Test log message 30 arg1 arg2", events.get(0).getLoggingEvent().getFormattedMessage());
Assert.assertEquals("Test log message 52 arg1 arg2", events.get(22).getLoggingEvent().getFormattedMessage());
LogCallback logCallback5 = new LogCallback();
distributedLogReader.getLog(loggingContext, allEvents.get(35).getLoggingEvent().getTimeStamp(),
allEvents.get(38).getLoggingEvent().getTimeStamp(), Filter.EMPTY_FILTER, logCallback5);
events = logCallback5.getEvents();
Assert.assertEquals(3, events.size());
Assert.assertEquals("Test log message 35 arg1 arg2", events.get(0).getLoggingEvent().getFormattedMessage());
Assert.assertEquals("Test log message 37 arg1 arg2", events.get(2).getLoggingEvent().getFormattedMessage());
LogCallback logCallback6 = new LogCallback();
distributedLogReader.getLog(loggingContext, allEvents.get(53).getLoggingEvent().getTimeStamp(),
allEvents.get(59).getLoggingEvent().getTimeStamp(), Filter.EMPTY_FILTER, logCallback6);
events = logCallback6.getEvents();
Assert.assertEquals(6, events.size());
Assert.assertEquals("Test log message 53 arg1 arg2", events.get(0).getLoggingEvent().getFormattedMessage());
Assert.assertEquals("Test log message 58 arg1 arg2", events.get(5).getLoggingEvent().getFormattedMessage());
LogCallback logCallback7 = new LogCallback();
distributedLogReader.getLog(loggingContext, allEvents.get(59).getLoggingEvent().getTimeStamp(),
allEvents.get(59).getLoggingEvent().getTimeStamp(), Filter.EMPTY_FILTER, logCallback7);
events = logCallback7.getEvents();
Assert.assertEquals(0, events.size());
LogCallback logCallback8 = new LogCallback();
distributedLogReader.getLog(loggingContext, allEvents.get(0).getLoggingEvent().getTimeStamp(),
allEvents.get(0).getLoggingEvent().getTimeStamp(), Filter.EMPTY_FILTER, logCallback8);
events = logCallback8.getEvents();
Assert.assertEquals(0, events.size());
LogCallback logCallback9 = new LogCallback();
distributedLogReader.getLog(loggingContext, allEvents.get(20).getLoggingEvent().getTimeStamp(),
allEvents.get(20).getLoggingEvent().getTimeStamp(), Filter.EMPTY_FILTER, logCallback9);
events = logCallback9.getEvents();
Assert.assertEquals(0, events.size());
LogCallback logCallback10 = new LogCallback();
distributedLogReader.getLog(loggingContext, allEvents.get(32).getLoggingEvent().getTimeStamp() - 999999,
allEvents.get(45).getLoggingEvent().getTimeStamp(), Filter.EMPTY_FILTER, logCallback10);
events = logCallback10.getEvents();
Assert.assertTrue(events.size() > 13);
Assert.assertEquals("Test log message 32 arg1 arg2",
events.get(events.size() - 13).getLoggingEvent().getFormattedMessage());
Assert.assertEquals("Test log message 44 arg1 arg2",
events.get(events.size() - 1).getLoggingEvent().getFormattedMessage());
LogCallback logCallback11 = new LogCallback();
distributedLogReader.getLog(loggingContext, allEvents.get(18).getLoggingEvent().getTimeStamp(),
allEvents.get(34).getLoggingEvent().getTimeStamp() + 999999,
Filter.EMPTY_FILTER, logCallback11);
events = logCallback11.getEvents();
Assert.assertTrue(events.size() > 16);
Assert.assertEquals("Test log message 18 arg1 arg2", events.get(0).getLoggingEvent().getFormattedMessage());
Assert.assertEquals("Test log message 33 arg1 arg2",
events.get(events.size() - 1 - (events.size() - 16)).getLoggingEvent().getFormattedMessage());
}
private Multimap<String, String> getPublishedKafkaMessages() throws InterruptedException {
final Multimap<String, String> contextMessages = ArrayListMultimap.create();
KAFKA_TESTER.getPublishedMessages(KAFKA_TESTER.getCConf().get(Constants.Logging.KAFKA_TOPIC),
ImmutableSet.of(0, 1), 300, 0, new Function<FetchedMessage, String>() {
@Override
public String apply(final FetchedMessage input) {
try {
Map.Entry<String, String> entry = convertFetchedMessage(input);
contextMessages.put(entry.getKey(), entry.getValue());
} catch (IOException e) {
LOG.error("Error while converting FetchedMessage {} ", e);
}
return "";
}
});
for (Map.Entry<String, Collection<String>> entry : contextMessages.asMap().entrySet()) {
LOG.info("Kafka Message Count for {} is {}", entry.getKey(), entry.getValue().size());
}
return contextMessages;
}
private Map.Entry<String, String> convertFetchedMessage(FetchedMessage message) throws IOException {
LoggingEventSerializer serializer = new LoggingEventSerializer();
ILoggingEvent iLoggingEvent = serializer.fromBytes(message.getPayload());
LoggingContext loggingContext = LoggingContextHelper.getLoggingContext(iLoggingEvent.getMDCPropertyMap());
String key = loggingContext.getLogPartition();
// Temporary map for pretty format
Map<String, String> tempMap = new HashMap<>();
tempMap.put("Timestamp", Long.toString(iLoggingEvent.getTimeStamp()));
tempMap.put("Partition", Long.toString(message.getTopicPartition().getPartition()));
tempMap.put("LogEvent", iLoggingEvent.getFormattedMessage());
return Maps.immutableEntry(key, gson.toJson(tempMap));
}
private static void publishLogs() throws Exception {
ByteArrayOutputStream bos = new ByteArrayOutputStream();
StatusPrinter.setPrintStream(new PrintStream(bos));
StatusPrinter.print((LoggerContext) LoggerFactory.getILoggerFactory());
ListeningExecutorService executor = MoreExecutors.listeningDecorator(Executors.newFixedThreadPool(3));
List<ListenableFuture<?>> futures = Lists.newArrayList();
futures.add(executor.submit(new LogPublisher(0, new FlowletLoggingContext("NS_1", "APP_1", "FLOW_1", "FLOWLET_1",
"RUN1", "INSTANCE1"))));
futures.add(executor.submit(new LogPublisher(0, new FlowletLoggingContext("NS_2", "APP_2", "FLOW_2", "FLOWLET_2",
"RUN1", "INSTANCE1"))));
futures.add(executor.submit(new LogPublisher(0, new ServiceLoggingContext("system", "services", "metrics"))));
// Make sure the final segments of logs are added at end to simplify checking for done in waitTillLogSaverDone
futures.add(executor.submit(new LogPublisher(60, new FlowletLoggingContext("NS_1", "APP_1", "FLOW_1", "FLOWLET_1",
"RUN2", "INSTANCE2"))));
futures.add(executor.submit(new LogPublisher(60, new FlowletLoggingContext("NS_2", "APP_2", "FLOW_2", "FLOWLET_2",
"RUN2", "INSTANCE2"))));
Futures.allAsList(futures).get();
System.out.println(bos.toString());
executor.shutdownNow();
}
private static class LogPublisher implements Runnable {
private final int startIndex;
private final LoggingContext loggingContext;
private LogPublisher(int startIndex, LoggingContext loggingContext) {
this.startIndex = startIndex;
this.loggingContext = loggingContext;
}
@Override
public void run() {
LoggingContextAccessor.setLoggingContext(loggingContext);
Logger logger = LoggerFactory.getLogger("LogSaverTest");
Exception e1 = new Exception("Test Exception1");
Exception e2 = new Exception("Test Exception2", e1);
int startBatch = startIndex / 10;
try {
for (int j = startBatch; j < startBatch + 6; ++j) {
for (int i = 0; i < 10; ++i) {
logger.warn("Test log message " + (10 * j + i) + " {} {}", "arg1", "arg2", e2);
if (j == startIndex && (i <= 3)) {
// For some events introduce the sleep of more than 8 seconds for windowing to take effect
TimeUnit.MILLISECONDS.sleep(300);
} else {
TimeUnit.MILLISECONDS.sleep(1);
}
}
TimeUnit.MILLISECONDS.sleep(1200);
}
} catch (InterruptedException e) {
e.printStackTrace();
Thread.currentThread().interrupt();
}
}
}
private static void waitTillLogSaverDone(Location logBaseDir, String filePattern, String logLine) throws Exception {
long start = System.currentTimeMillis();
while (true) {
Location latestFile = getLatestFile(logBaseDir, filePattern);
if (latestFile != null) {
AvroFileReader logReader = new AvroFileReader(new LogSchema().getAvroSchema());
LogCallback logCallback = new LogCallback();
logCallback.init();
logReader.readLog(latestFile, Filter.EMPTY_FILTER, 0, Long.MAX_VALUE, Integer.MAX_VALUE, logCallback);
logCallback.close();
List<LogEvent> events = logCallback.getEvents();
if (events.size() > 0) {
LogEvent event = events.get(events.size() - 1);
if (event.getLoggingEvent().getFormattedMessage().equals(logLine)) {
break;
}
}
}
Assert.assertTrue("Time exceeded", System.currentTimeMillis() - start < 30 * 1000);
TimeUnit.MILLISECONDS.sleep(30);
}
LOG.info("Done waiting!");
TimeUnit.SECONDS.sleep(1);
}
private static Location getLatestFile(Location logBaseDir, String filePattern) throws Exception {
String date = new SimpleDateFormat("yyyy-MM-dd").format(new Date());
Location dir = logBaseDir.append(String.format(filePattern, date));
if (!dir.exists()) {
return null;
}
List<Location> files = dir.list();
if (files.isEmpty()) {
return null;
}
SortedMap<Long, Location> map = Maps.newTreeMap();
for (Location file : files) {
String filename = FilenameUtils.getBaseName(file.getName());
map.put(Long.parseLong(filename), file);
}
return map.get(map.lastKey());
}
}