blob: ff1cf222c636a9961be3f3c9bf769b23eca915de [file] [log] [blame]
package org.apache.solr;
/*
* 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.
*/
import java.util.Collections;
import java.util.HashMap;
import java.util.Map;
import java.util.WeakHashMap;
import java.util.logging.ConsoleHandler;
import java.util.logging.Formatter;
import java.util.logging.Handler;
import java.util.logging.Level;
import java.util.logging.LogRecord;
import java.util.logging.Logger;
import org.apache.solr.cloud.ZkController;
import org.apache.solr.common.SolrException;
import org.apache.solr.common.cloud.Replica;
import org.apache.solr.core.SolrCore;
import org.apache.solr.request.SolrQueryRequest;
import org.apache.solr.request.SolrRequestInfo;
import org.slf4j.LoggerFactory;
public class SolrLogFormatter extends Formatter {
/** Add this interface to a thread group and the string returned by
* getTag() will appear in log statements of any threads under that group.
*/
public static interface TG {
public String getTag();
}
long startTime = System.currentTimeMillis();
long lastTime = startTime;
Map<Method, String> methodAlias = new HashMap<>();
public static class Method {
public String className;
public String methodName;
public Method(String className, String methodName) {
this.className = className;
this.methodName = methodName;
}
@Override
public int hashCode() {
return className.hashCode() + methodName.hashCode();
}
@Override
public boolean equals(Object obj) {
if (!(obj instanceof Method)) return false;
Method other = (Method)obj;
return (className.equals(other.className) && methodName.equals(other.methodName));
}
@Override
public String toString() {
return className + '.' + methodName;
}
}
public SolrLogFormatter() {
super();
methodAlias.put(new Method("org.apache.solr.update.processor.LogUpdateProcessor","finish"), "UPDATE");
methodAlias.put(new Method("org.apache.solr.core.SolrCore","execute"), "REQ");
}
// TODO: name this better... it's only for cloud tests where every core container has just one solr server so Port/Core are fine
public boolean shorterFormat = false;
/** Removes info that is redundant for current cloud tests including core name, webapp, and common labels path= and params=
* [] webapp=/solr path=/select params={q=foobarbaz} hits=0 status=0 QTime=1
* /select {q=foobarbaz} hits=0 status=0 QTime=1
* NOTE: this is a work in progress and different settings may be ideal for other types of tests.
*/
public void setShorterFormat() {
shorterFormat = true;
// looking at /update is enough... we don't need "UPDATE /update"
methodAlias.put(new Method("org.apache.solr.update.processor.LogUpdateProcessor","finish"), "");
}
public static class CoreInfo {
static int maxCoreNum;
String shortId;
String url;
Map<String, Object> coreProps;
}
Map<SolrCore, CoreInfo> coreInfoMap = new WeakHashMap<>(); // TODO: use something that survives across a core reload?
public Map<String,String> classAliases = new HashMap<>();
@Override
public String format(LogRecord record) {
try {
return _format(record);
} catch (Exception e) {
// logging swallows exceptions, so if we hit an exception we need to convert it to a string to see it
return "ERROR IN SolrLogFormatter! original message:" + record.getMessage() + "\n\tException: " + SolrException.toStr(e);
}
}
public void appendThread(StringBuilder sb, LogRecord record) {
Thread th = Thread.currentThread();
/******
sb.append(" T=");
sb.append(th.getName()).append(' ');
// NOTE: tried creating a thread group around jetty but we seem to lose it and request
// threads are in the normal "main" thread group
ThreadGroup tg = th.getThreadGroup();
while (tg != null) {
sb.append("(group_name=").append(tg.getName()).append(")");
if (tg instanceof TG) {
sb.append(((TG)tg).getTag());
sb.append('/');
}
try {
tg = tg.getParent();
} catch (Throwable e) {
tg = null;
}
}
******/
// NOTE: LogRecord.getThreadID is *not* equal to Thread.getId()
sb.append(" T");
sb.append(th.getId());
}
public String _format(LogRecord record) {
String message = record.getMessage();
StringBuilder sb = new StringBuilder(message.length() + 80);
long now = record.getMillis();
long timeFromStart = now - startTime;
long timeSinceLast = now - lastTime;
lastTime = now;
String shortClassName = getShortClassName(record.getSourceClassName(), record.getSourceMethodName());
/***
sb.append(timeFromStart).append(' ').append(timeSinceLast);
sb.append(' ');
sb.append(record.getSourceClassName()).append('.').append(record.getSourceMethodName());
sb.append(' ');
sb.append(record.getLevel());
***/
SolrRequestInfo requestInfo = SolrRequestInfo.getRequestInfo();
SolrQueryRequest req = requestInfo == null ? null : requestInfo.getReq();
SolrCore core = req == null ? null : req.getCore();
ZkController zkController = null;
CoreInfo info = null;
if (core != null) {
info = coreInfoMap.get(core);
if (info == null) {
info = new CoreInfo();
info.shortId = "C"+Integer.toString(CoreInfo.maxCoreNum++);
coreInfoMap.put(core, info);
if (sb.length() == 0) sb.append("ASYNC ");
sb.append(" NEW_CORE "+info.shortId);
sb.append(" name=" + core.getName());
sb.append(" " + core);
}
if (zkController == null) {
zkController = core.getCoreDescriptor().getCoreContainer().getZkController();
}
if (zkController != null) {
if (info.url == null) {
info.url = zkController.getBaseUrl() + "/" + core.getName();
sb.append(" url="+info.url + " node="+zkController.getNodeName());
}
Map<String, Object> coreProps = getReplicaProps(zkController, core);
if (info.coreProps == null || !coreProps.equals(info.coreProps)) {
info.coreProps = coreProps;
final String corePropsString = "coll:" + core.getCoreDescriptor().getCloudDescriptor().getCollectionName() + " core:" + core.getName() + " props:" + coreProps;
sb.append(" " + info.shortId + "_STATE=" + corePropsString);
}
}
}
if (sb.length() > 0) sb.append('\n');
sb.append(timeFromStart);
// sb.append("\nL").append(record.getSequenceNumber()); // log number is useful for sequencing when looking at multiple parts of a log file, but ms since start should be fine.
appendThread(sb, record);
if (info != null) {
sb.append(' ').append(info.shortId); // core
}
if (zkController != null) {
sb.append(" P").append(zkController.getHostPort()); // todo: should be able to get this from core container for non zk tests
}
if (shortClassName.length() > 0) {
sb.append(' ').append(shortClassName);
}
if (record.getLevel() != Level.INFO) {
sb.append(' ').append(record.getLevel());
}
sb.append(' ');
appendMultiLineString(sb, message);
Throwable th = record.getThrown();
if (th != null) {
sb.append(' ');
String err = SolrException.toStr(th);
String ignoredMsg = SolrException.doIgnore(th, err);
if (ignoredMsg != null) {
sb.append(ignoredMsg);
} else {
sb.append(err);
}
}
sb.append('\n');
/*** Isn't core specific... prob better logged from zkController
if (info != null) {
ClusterState clusterState = zkController.getClusterState();
if (info.clusterState != clusterState) {
// something has changed in the matrix...
sb.append(zkController.getBaseUrl() + " sees new ClusterState:");
}
}
***/
return sb.toString();
}
private Map<String,Object> getReplicaProps(ZkController zkController, SolrCore core) {
final String collection = core.getCoreDescriptor().getCloudDescriptor().getCollectionName();
Replica replica = zkController.getClusterState().getReplica(collection, core.getCoreDescriptor().getCloudDescriptor().getCoreNodeName());
if(replica!=null) {
return replica.getProperties();
}
return Collections.EMPTY_MAP;
}
private Method classAndMethod = new Method(null,null); // don't need to be thread safe
private String getShortClassName(String name, String method) {
classAndMethod.className = name;
classAndMethod.methodName = method;
String out = methodAlias.get(classAndMethod);
if (out != null) return out;
StringBuilder sb = new StringBuilder();
int lastDot = name.lastIndexOf('.');
if (lastDot < 0) return name + '.' + method;
int prevIndex = -1;
for (;;) {
char ch = name.charAt(prevIndex + 1);
sb.append(ch);
int idx = name.indexOf('.', prevIndex+1);
ch = name.charAt(idx+1);
if (idx >= lastDot || Character.isUpperCase(ch)) {
sb.append(name.substring(idx));
break;
}
prevIndex = idx;
}
return sb.toString() + '.' + method;
}
private void addFirstLine(StringBuilder sb, String msg) {
// INFO: [] webapp=/solr path=/select params={q=foobarbaz} hits=0 status=0 QTime=1
if (!shorterFormat || !msg.startsWith("[")) {
sb.append(msg);
return;
}
int idx = msg.indexOf(']');
if (idx < 0 || !msg.startsWith(" webapp=", idx+1)) {
sb.append(msg);
return;
}
idx = msg.indexOf(' ',idx+8); // space after webapp=
if (idx < 0) { sb.append(msg); return; }
idx = msg.indexOf('=',idx+1); // = in path=
if (idx < 0) { sb.append(msg); return; }
int idx2 = msg.indexOf(' ',idx+1);
if (idx2 < 0) { sb.append(msg); return; }
sb.append(msg.substring(idx+1, idx2+1)); // path
idx = msg.indexOf("params=", idx2);
if (idx < 0) {
sb.append(msg.substring(idx2));
} else {
sb.append(msg.substring(idx+7));
}
}
private void appendMultiLineString(StringBuilder sb, String msg) {
int idx = msg.indexOf('\n');
if (idx < 0) {
addFirstLine(sb, msg);
return;
}
int lastIdx = -1;
for (;;) {
if (idx < 0) {
if (lastIdx == -1) {
addFirstLine(sb, msg.substring(lastIdx+1));
} else {
sb.append(msg.substring(lastIdx+1));
}
break;
}
if (lastIdx == -1) {
addFirstLine(sb, msg.substring(lastIdx+1, idx));
} else {
sb.append(msg.substring(lastIdx+1, idx));
}
sb.append("\n\t");
lastIdx = idx;
idx = msg.indexOf('\n',lastIdx+1);
}
}
@Override
public String getHead(Handler h) {
return super.getHead(h);
}
@Override
public String getTail(Handler h) {
return super.getTail(h);
}
@Override
public String formatMessage(LogRecord record) {
return format(record);
}
static ThreadLocal<String> threadLocal = new ThreadLocal<>();
public static void main(String[] args) throws Exception {
Handler[] handlers = Logger.getLogger("").getHandlers();
boolean foundConsoleHandler = false;
for (int index = 0; index < handlers.length; index++) {
// set console handler to SEVERE
if (handlers[index] instanceof ConsoleHandler) {
handlers[index].setLevel(Level.ALL);
handlers[index].setFormatter(new SolrLogFormatter());
foundConsoleHandler = true;
}
}
if (!foundConsoleHandler) {
// no console handler found
System.err.println("No consoleHandler found, adding one.");
ConsoleHandler consoleHandler = new ConsoleHandler();
consoleHandler.setLevel(Level.ALL);
consoleHandler.setFormatter(new SolrLogFormatter());
Logger.getLogger("").addHandler(consoleHandler);
}
final org.slf4j.Logger log = LoggerFactory.getLogger(SolrLogFormatter.class);
log.error("HELLO");
ThreadGroup tg = new MyThreadGroup("YCS");
Thread th = new Thread(tg, "NEW_THREAD") {
@Override
public void run() {
try {
go();
} catch (Exception e) {
e.printStackTrace();
}
}
};
th.start();
th.join();
}
static class MyThreadGroup extends ThreadGroup implements TG {
public MyThreadGroup(String name) {
super(name);
}
@Override
public String getTag() { return "HELLO"; }
}
public static void go() throws Exception {
final org.slf4j.Logger log = LoggerFactory.getLogger(SolrLogFormatter.class);
Thread thread1 = new Thread() {
@Override
public void run() {
threadLocal.set("from thread1");
log.error("[] webapp=/solr path=/select params={hello} wow");
}
};
Thread thread2 = new Thread() {
@Override
public void run() {
threadLocal.set("from thread2");
log.error("InThread2");
}
};
thread1.start();
thread2.start();
thread1.join();
thread2.join();
}
}