blob: 17d3312ceddadc211ea3d35f6ff3856757a8feea [file] [log] [blame]
/*
* Licensed to the Apache Software Foundation (ASF) under one
* or more contributor license agreements. See the NOTICE file
* distributed with this work for additional information
* regarding copyright ownership. The ASF licenses this file
* to you 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 org.apache.sling.tracer.internal;
import java.io.ByteArrayInputStream;
import java.io.ByteArrayOutputStream;
import java.io.IOException;
import java.io.InputStream;
import java.io.InputStreamReader;
import java.io.OutputStream;
import java.io.OutputStreamWriter;
import java.io.PrintWriter;
import java.io.Reader;
import java.io.StringWriter;
import java.io.UnsupportedEncodingException;
import java.io.Writer;
import java.util.ArrayList;
import java.util.Collections;
import java.util.HashSet;
import java.util.Iterator;
import java.util.List;
import java.util.Set;
import java.util.zip.GZIPInputStream;
import java.util.zip.GZIPOutputStream;
import javax.servlet.http.HttpServletRequest;
import ch.qos.logback.classic.Level;
import com.google.common.primitives.Longs;
import org.apache.commons.io.IOUtils;
import org.apache.felix.utils.json.JSONWriter;
import org.apache.sling.api.request.RequestProgressTracker;
import org.jetbrains.annotations.NotNull;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.helpers.FormattingTuple;
import org.slf4j.helpers.MessageFormatter;
import static com.google.common.base.Preconditions.checkArgument;
import static org.apache.sling.tracer.internal.Util.count;
import static org.apache.sling.tracer.internal.Util.nullSafeString;
import static org.apache.sling.tracer.internal.Util.nullSafeTrim;
class JSONRecording implements Recording, Comparable<JSONRecording> {
private static final String[] QUERY_API_PKGS = {
"org.apache.sling.resourceresolver", //Sling package would come first in stack so listed first
"org.apache.jackrabbit.oak"
};
private static final Object[] EMPTY = new Object[0];
private static final Logger log = LoggerFactory.getLogger(JSONRecording.class);
public static final String OAK_QUERY_PKG = "org.apache.jackrabbit.oak.query";
private final String method;
private final String requestId;
private final String uri;
private final boolean compress;
private final List<QueryEntry> queries = new ArrayList<QueryEntry>();
private final List<LogEntry> logs = new ArrayList<LogEntry>();
private final Set<String> loggerNames = new HashSet<String>();
private RequestProgressTracker tracker;
private byte[] json;
private final long start = System.currentTimeMillis();
private long timeTaken;
private final QueryLogCollector queryCollector = new QueryLogCollector();
private final CallerFinder queryCallerFinder = new CallerFinder(QUERY_API_PKGS);
public JSONRecording(String requestId, HttpServletRequest r, boolean compress) {
this.requestId = requestId;
this.compress = compress;
this.method = r.getMethod();
this.uri = r.getRequestURI();
}
public boolean render(Writer w) throws IOException {
if (json != null) {
Reader r = new InputStreamReader(getInputStream(false), "UTF-8");
IOUtils.copy(r, w);
return true;
}
return false;
}
public boolean render(OutputStream os, boolean compressed) throws IOException {
if (json != null) {
IOUtils.copyLarge(getInputStream(compressed), os);
return true;
}
return false;
}
public int size() {
if (json != null){
return json.length;
}
return 0;
}
public String getUri() {
return uri;
}
public String getRequestId() {
return requestId;
}
public long getTimeTaken() {
return timeTaken;
}
public long getStart() {
return start;
}
//~---------------------------------------< Recording >
@Override
public void log(TracerConfig tc, Level level, String logger, FormattingTuple tuple) {
if (logger.startsWith(OAK_QUERY_PKG)) {
queryCollector.record(level, logger, tuple);
}
logs.add(new LogEntry(tc, level, logger, tuple));
}
@Override
public void registerTracker(RequestProgressTracker tracker) {
this.tracker = tracker;
}
@Override
public void recordCategory(String loggerName) {
loggerNames.add(loggerName);
}
public void done() {
try {
if (json == null) {
json = toJSON();
//Let the tracker and other references go to
//not occupy memory
tracker = null;
queries.clear();
logs.clear();
}
} catch (UnsupportedEncodingException e) {
log.warn("Error occurred while converting the log data for request {} to JSON", requestId, e);
} catch (IOException e) {
log.warn("Error occurred while converting the log data for request {} to JSON", requestId, e);
}
}
private byte[] toJSON() throws IOException {
ByteArrayOutputStream baos = new ByteArrayOutputStream();
OutputStream os = baos;
if (compress) {
os = new GZIPOutputStream(os);
}
OutputStreamWriter osw = new OutputStreamWriter(os, "UTF-8");
JSONWriter jw = new JSONWriter(osw);
jw.object();
jw.key("method").value(method);
timeTaken = System.currentTimeMillis() - start;
jw.key("time").value(timeTaken);
jw.key("timestamp").value(start);
addRequestProgressLogs(jw);
queryCollector.done();
addJson(jw, "queries", queries);
addJson(jw, "logs", logs);
addLoggerNames(jw);
jw.endObject();
osw.flush();
os.close();
return baos.toByteArray();
}
private void addLoggerNames(JSONWriter jw) throws IOException {
List<String> sortedNames = new ArrayList<String>(loggerNames);
Collections.sort(sortedNames);
jw.key("loggerNames");
jw.array();
for (String o : sortedNames) {
jw.value(o);
}
jw.endArray();
}
private void addRequestProgressLogs(JSONWriter jw) throws IOException {
if (tracker != null) {
jw.key("requestProgressLogs");
jw.array();
Iterator<String> it = tracker.getMessages();
//Per docs iterator can be null
while (it != null && it.hasNext()) {
String entry = it.next();
if (entry != null){
jw.value(entry.trim());
}
}
jw.endArray();
}
}
private void addJson(JSONWriter jw, String name, List<? extends JsonEntry> entries) throws IOException {
jw.key(name);
jw.array();
for (JsonEntry je : entries) {
jw.object();
je.toJson(jw);
jw.endObject();
}
jw.endArray();
}
private InputStream getInputStream(boolean compressed) throws IOException {
InputStream is = new ByteArrayInputStream(json);
if (compressed) {
checkArgument(compress, "Cannot provide compressed response with compression disabled");
return is;
}
if (compress) {
is = new GZIPInputStream(is);
}
return is;
}
@Override
public int compareTo(@NotNull JSONRecording o) {
return Longs.compare(start, o.start);
}
private interface JsonEntry {
void toJson(JSONWriter jw) throws IOException;
}
private static class LogEntry implements JsonEntry {
final Level level;
final String logger;
final FormattingTuple tuple;
final String[] params;
final long timestamp = System.currentTimeMillis();
final List<StackTraceElement> caller;
private LogEntry(TracerConfig tc, Level level, String logger, FormattingTuple tuple) {
this.level = level != null ? level : Level.INFO;
this.logger = logger;
this.tuple = tuple;
this.params = getParams(tuple);
this.caller = getCallerData(tc);
}
private static List<StackTraceElement> getCallerData(TracerConfig tc) {
if (tc.isReportCallerStack()){
return tc.getCallerReporter().report();
}
return Collections.emptyList();
}
private static String[] getParams(FormattingTuple tuple) {
//Eagerly convert arg to string so that if arg is bound by context like
//session then it gets evaluated when that is valid i.e. at time of call itself
Object[] params = tuple.getArgArray();
String[] strParams = null;
if (params != null){
strParams = new String[params.length];
for (int i = 0; i < params.length; i++) {
strParams[i] = toString(params[i]);
}
}
return strParams;
}
private static String toString(Object o) {
//Make use of Slf4j null safe toString support!
return MessageFormatter.format("{}", o).getMessage();
}
private static String getStackTraceAsString(Throwable throwable) {
StringWriter stringWriter = new StringWriter();
throwable.printStackTrace(new PrintWriter(stringWriter));
return stringWriter.toString();
}
@Override
public void toJson(JSONWriter jw) throws IOException {
jw.key("timestamp").value(timestamp);
jw.key("level").value(level.levelStr);
jw.key("logger").value(logger);
jw.key("message").value(tuple.getMessage());
if (params != null) {
jw.key("params");
jw.array();
for (String o : params) {
jw.value(o);
}
jw.endArray();
}
Throwable t = tuple.getThrowable();
if (t != null) {
//Later we can look into using Logback Throwable handling
jw.key("exception").value(getStackTraceAsString(t));
}
if (!caller.isEmpty()){
jw.key("caller");
jw.array();
for (StackTraceElement o : caller) {
jw.value(o.toString());
}
jw.endArray();
}
}
}
private static class QueryEntry implements JsonEntry {
final String query;
final String plan;
final String caller;
private QueryEntry(String query, String plan, String caller) {
this.query = query;
this.plan = plan;
this.caller = caller;
}
@Override
public void toJson(JSONWriter jw) throws IOException {
jw.key("query").value(query);
jw.key("plan").value(plan);
jw.key("caller").value(caller);
}
}
private class QueryLogCollector {
String query;
String plan;
String caller;
int subPlans = 0;
public void record(Level level, String logger, FormattingTuple tuple) {
//Assuming in a series of log statement from query package we see 'query'
//and then 'plan' then once both are not null then it means that one query
//execution is complete and we push the entry and reset the state
//This is done as we do not have a definitive way to determine when
//a given query processing is done
attemptQueryEntry();
//TODO Query time. Change Oak to provide this information via some
//dedicated Audit logging such that below reliance on impl details
//can be avoided
String msg = tuple.getMessage();
if (Level.DEBUG == level && msg != null) {
Object[] args = tuple.getArgArray() == null ? EMPTY : tuple.getArgArray();
if (query == null){
if ("org.apache.jackrabbit.oak.query.QueryEngineImpl".equals(logger)
&& msg.contains("Parsing") && args.length == 2){
//LOG.debug("Parsing {} statement: {}", language, statement);
query = nullSafeString(args[1]);
caller = determineCaller();
}
}
//Plan for union query are logged separately
if (plan == null){
if ("org.apache.jackrabbit.oak.query.QueryImpl".equals(logger)
&& msg.startsWith("query plan ")){
//logDebug("query execute " + statement);
if (subPlans == 0) {
plan = msg.substring("query plan ".length());
} else {
subPlans--;
}
} else if ("org.apache.jackrabbit.oak.query.UnionQueryImpl".equals(logger)
&& msg.contains("query union plan") && args.length > 0){
// LOG.debug("query union plan {}", getPlan());
plan = nullSafeString(args[0]);
// Determine number of sub-queries in this UNION query so they can be ignored
int unionCount = count(plan, "*/ union ");
if (unionCount > 0) {
subPlans = unionCount + 1;
}
}
}
}
}
private String determineCaller() {
StackTraceElement caller = queryCallerFinder.determineCaller(Thread.currentThread().getStackTrace());
if (caller != null) {
return caller.toString();
}
return null;
}
/**
* Checks if both plan and query are determined. If yes then pushes them to list
* and resets the state.
*/
public void attemptQueryEntry(){
if (query != null && plan != null){
queries.add(new QueryEntry(nullSafeTrim(query), nullSafeTrim(plan), caller));
plan = query = null;
}
}
public void done(){
//Push any last pending entry i.e. last query
attemptQueryEntry();
}
}
}