/*
* Copyright (c) 2013. SlickLog.
*/
package com.slicklog.remotelogger;
import com.slicklog.remotelogger.exceptions.CannotEnstablishConnectionException;
import com.slicklog.remotelogger.exceptions.SlickLogRemoteLoggerException;
import java.io.BufferedOutputStream;
import java.io.IOException;
import java.io.OutputStream;
import java.net.HttpURLConnection;
import java.util.ArrayList;
import java.util.LinkedList;
import java.util.List;
import java.util.ListIterator;
import java.util.concurrent.BlockingQueue;
import java.util.concurrent.LinkedBlockingQueue;
import java.util.concurrent.TimeUnit;
/**
*
* @author Torindo Nesci
*/
public class SlickLogRemoteLogger implements Constants {
private static final String LOGGER_SPAWNER_THREAD_NAME = "SlickLogRemoteLoggerSpawner";
private static final String LOGGER_THREAD_NAME = "SlickLogRemoteLogger";
private static final String LOGGER_FINALIZER_THREAD_NAME = "SlickLogFinalizerRemoteLogger";
//
private static final int MAX_WAIT_ON_ERROR = 10000;
private static final int MIN_WAIT = 10;
private static final int MAX_WAIT_ON_QUEUE_EMPTY = 2000;
//
private final InternalLogger mLogger;
private final SlickLogConnectionBuilder mConnBuilder;
private final boolean mSpawnNewThreads;
private volatile Thread mLoggerSpwnerThread;
//
private volatile BlockingQueue<String> mLogQueue = new LinkedBlockingQueue<String>(LOG_RECORDS_QUEUE_SIZE);
private volatile boolean mStopped = false;
private volatile boolean mInitialized = false;
public SlickLogRemoteLogger(
SlickLogConnectionBuilder connBuilder, InternalLogger logger, boolean spawnNewThreads) {
mConnBuilder = connBuilder;
mLogger = logger;
mSpawnNewThreads = spawnNewThreads;
}
public void init() {
if (mInitialized) {
throw new IllegalStateException("Remote logger already initialized");
}
attachRuntimeHook();
startRemoteLoggeSpawnerThread();
mInitialized = true;
}
public void enqueueRecord(String logRecord) {
mLogger.info("Enqueueing %s.", logRecord);
BlockingQueue<String> queue = mLogQueue;
boolean success = queue.offer(logRecord);
if (!success) {
mLogger.error("Log Records Queue is Full. Lost Log Record: %s", logRecord);
}
}
private void startRemoteLoggeSpawnerThread() {
mLoggerSpwnerThread = new Thread(
getLoggerSpawner(), LOGGER_SPAWNER_THREAD_NAME);
mLoggerSpwnerThread.setDaemon(true);
mLoggerSpwnerThread.start();
}
private Runnable getLoggerSpawner() {
return new Runnable() {
@Override
public void run() {
long errorWait = MIN_WAIT;
while (!mStopped) {
try {
long queueEmptyWait = MIN_WAIT;
while (mLogQueue.isEmpty()) {
Thread.sleep(queueEmptyWait);
queueEmptyWait *= 2;
if (queueEmptyWait > MAX_WAIT_ON_QUEUE_EMPTY) {
queueEmptyWait = MAX_WAIT_ON_QUEUE_EMPTY;
}
}
mLogger.info("Queue is no longer empty.");
if (mSpawnNewThreads) {
mLogger.info("Spawning new Logger.");
Thread loggerThread = new Thread(
getRemoteLoggerRunnable(), LOGGER_THREAD_NAME);
loggerThread.setDaemon(false);
loggerThread.start();
//join without timout might run forever even though if the spawned thread finished.
while (loggerThread.isAlive() && !mStopped) {
loggerThread.join(1000);
}
errorWait = MIN_WAIT;
} else {
getRemoteLoggerRunnable().run();
}
} catch (Throwable cause) {
mLogger.error("An error occurred while creating logger thread: %s", cause);
try {
Thread.sleep(errorWait);
} catch (InterruptedException ex) {
mLogger.error("An error occurred while sleaping thread: %s", ex);
}
errorWait *= 2;
if (errorWait > MAX_WAIT_ON_ERROR) {
errorWait = MAX_WAIT_ON_ERROR;
}
}
}
mLogger.info("Logger Stopped.");
}
};
}
private void attachRuntimeHook() {
Thread finalizerHook = new Thread(
getFinalizerRemoteLoggerRunnable(), LOGGER_FINALIZER_THREAD_NAME);
finalizerHook.setDaemon(true);
Runtime.getRuntime().addShutdownHook(finalizerHook);
}
private Runnable getFinalizerRemoteLoggerRunnable() {
return new Runnable() {
@Override
public void run() {
mLogger.info("Collecting and sending last log records.");
mStopped = true;
boolean greedy = true;
try {
synchronized (SlickLogRemoteLogger.this) {
int records;
do {
records = remoteLog(greedy);
mLogger.info("Log Records Pushed Successfully: %s", records);
} while (records > 0);
}
} catch (Throwable cause) {
mLogger.error("An error occurred while sending logs "
+ "data to Slicklog.com", cause);
}
} //run()
};
}
private Runnable getRemoteLoggerRunnable() {
return new Runnable() {
@Override
public void run() {
synchronized (SlickLogRemoteLogger.this) {
try {
boolean greedy = false;
int records = remoteLog(greedy);
mLogger.info("Log Records Pushed Successfully: %s", records);
} catch (Throwable cause) {
mLogger.error("An error occurred while sending logs "
+ "data to Slicklog.com: %s.", cause);
}
}
} //run()
};
}
private int remoteLog(boolean greedy) throws IOException, InterruptedException {
List<byte[]> logRecords = collectLogRecords(greedy);
if (logRecords.isEmpty()) {
mLogger.info("No Log Records Collected.");
return 0;
}
ListIterator<byte[]> logRecordsIt = logRecords.listIterator();
while (logRecordsIt.hasNext()) {
remoteLogRecords(logRecordsIt);
}
return logRecords.size();
}
private void remoteLogRecords(ListIterator<byte[]> logRecordsIt) throws InterruptedException {
long wait = 100;
int retryCount = 0;
boolean retryPush;
boolean success;
do {
try {
int statusCode = pushLogRecords(logRecordsIt);
success = isSuccess(statusCode);
if (!success) {
mLogger.error("Log events push failed.");
retryPush = isErrorRecoverable(statusCode);
} else {
mLogger.info("Log Records push succeeded.");
retryPush = false;
}
} catch (Throwable cause) {
mLogger.error("An error occurred while pushing log records %s.", cause.toString());
success = false;
retryPush = true;
}
if (retryPush) {
Thread.sleep(wait);
wait *= 2;
}
} while (retryPush && retryCount++ < MAX_ERROR_RETRY);
if (retryCount >= MAX_ERROR_RETRY) {
throw new SlickLogRemoteLoggerException("Could Not Send Log "
+ "Records To Slicklog.com. Max Retry exceeded.");
} else if (!success) {
throw new SlickLogRemoteLoggerException("An unrecoverable error occurred.");
}
}
private boolean isSuccess(int statusCode) {
return statusCode == API_RESP_CODE_OK;
}
private boolean isErrorRecoverable(int statusCode) {
char errorClass = ("" + statusCode).charAt(0);
mLogger.info("Error class is %cxx.", errorClass);
return errorClass != '4' && errorClass != '2';
}
private HttpURLConnection buildConnection() throws InterruptedException {
long wait = MIN_WAIT;
for (int i = 0; i < MAX_ERROR_RETRY; i++) {
try {
return mConnBuilder.buildNewConnection();
} catch (Throwable cause) {
mLogger.error("Cannot build connection. Trying again later: %s.", cause);
}
Thread.sleep(wait);
wait *= 2;
}
throw new CannotEnstablishConnectionException();
}
private boolean isCollectTimePassed(long timeStart, boolean greedy) {
return System.currentTimeMillis() - timeStart > MAX_COLLECT_TIME
|| (mStopped && !greedy);
}
private String poll(long timeStart, boolean greedy) throws InterruptedException {
long maxWait = 0;
if (!greedy) {
maxWait = MAX_COLLECT_TIME - (System.currentTimeMillis() - timeStart);
if (maxWait < 0) {
return null;
}
}
long wait = Math.min(maxWait, MAX_QUEUE_WAIT);
long pollingStart = System.currentTimeMillis();
long elapsed = 0;
while (elapsed <= maxWait) {
String data = mLogQueue.poll(wait, TimeUnit.MILLISECONDS);
if (data != null || mStopped) {
return data;
}
elapsed = System.currentTimeMillis() - pollingStart;
}
return null;
}
private List<byte[]> collectLogRecords(boolean greedy) throws InterruptedException {
mLogger.info("Collecting log events.");
LinkedList<byte[]> logRecords = new LinkedList<byte[]>();
long logRecordsSize = 0;
try {
long timeStart = System.currentTimeMillis();
while (logRecordsSize < MAX_SIZE_TO_SEND && !isCollectTimePassed(timeStart, greedy)) {
String logRecord = poll(timeStart, greedy);
if (logRecord == null) {
mLogger.info("No log message found in queue.");
break;
}
byte[] buff = logRecord.getBytes(CHARSET);
logRecordsSize += buff.length;
logRecords.add(buff);
mLogger.info("Collected log recod: %s", logRecord);
}
} catch (Throwable cause) {
mLogger.error("An error occurred while collecting log events."
+ "Pushing log records already collected: %s.", cause);
}
if (logRecordsSize > MAX_SIZE_CHUNK) {
byte[] last = logRecords.removeLast();
List<byte[]> splits = split(last, MAX_SIZE_CHUNK);
logRecords.addAll(splits);
}
return logRecords;
}
private static List<byte[]> split(byte[] arr, int maxSize) {
List<byte[]> arrs = new ArrayList<byte[]>(arr.length / maxSize + 1);
int idx = 0;
while (idx < arr.length) {
int length = Math.min(maxSize, arr.length - idx);
byte[] split = new byte[length];
System.arraycopy(arr, idx, split, 0, length);
arrs.add(split);
idx += length;
}
return arrs;
}
private int pushLogRecords(ListIterator<byte[]> logRecordsIt)
throws IOException, InterruptedException {
mLogger.info("Pushing log records.");
HttpURLConnection conn = buildConnection();
try {
OutputStream out = conn.getOutputStream();
BufferedOutputStream bout = new BufferedOutputStream(out);
pushLogRecords(bout, logRecordsIt);
bout.flush();
bout.close();
int retCode = conn.getResponseCode();
if (retCode != API_RESP_CODE_OK) {
String errorMsg = conn.getHeaderField(HEADER_ERROR_FIELD);
mLogger.error("Request error code=%s,message=%s", retCode, errorMsg);
}
return retCode;
} finally {
try {
conn.disconnect();
} catch (Throwable cause) {
mLogger.error("An error occurred while closing connection: %s.", cause.getMessage());
}
}
}
private void pushLogRecords(OutputStream out, ListIterator<byte[]> logRecordsIt)
throws IOException {
long size = 0;
while (logRecordsIt.hasNext()) {
byte[] logRecord = logRecordsIt.next();
size += logRecord.length;
if (size > MAX_SIZE_CHUNK) {
logRecordsIt.previous();
return;
}
out.write(logRecord);
if (mLogger.isLoggerEnabled()) {
mLogger.info("Log Record Push Initiated:%s", new String(logRecord));
}
}
}
}