SOLR-3157: improve test logging

git-svn-id: https://svn.apache.org/repos/asf/lucene/dev/trunk@1294212 13f79535-47bb-0310-9956-ffa450edef68

solr/core/src/java/org/apache/solr/SolrLogFormatter.java

@@ -0,0 +1,372 @@
+package org.apache.solr;
+
+
+import org.apache.solr.cloud.ZkController;
+import org.apache.solr.common.SolrException;
+import org.apache.solr.common.cloud.CloudState;
+import org.apache.solr.common.cloud.CoreState;
+import org.apache.solr.core.SolrCore;
+import org.apache.solr.request.SolrQueryRequest;
+import org.apache.solr.request.SolrRequestInfo;
+import org.slf4j.LoggerFactory;
+
+import java.util.HashMap;
+import java.util.Map;
+import java.util.WeakHashMap;
+import java.util.logging.*;
+
+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<Method, String>();
+  
+  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;
+    }
+  }
+  
+  
+
+  
+  protected 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");
+  }
+
+  public static class CoreInfo {
+    public static int maxCoreNum;
+    public String shortId;
+    public String url;
+    CoreState coreState;  // should be fine to keep a hard reference to this
+    // CloudState cloudState;  // should be fine to keep this hard reference since cloudstate is immutable and doesn't have pointers to anything heavyweight (like SolrCore, CoreContainer, etc)
+  }
+
+  Map<SolrCore, CoreInfo> coreInfoMap = new WeakHashMap<SolrCore, CoreInfo>();    // TODO: use something that survives across a core reload?
+
+  public Map<String,String> classAliases = new HashMap<String, String>();
+
+  @Override
+  public String format(LogRecord record) {
+    try {
+      return _format(record);
+    } catch (Throwable th) {
+      // 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(th);
+    }
+  }
+
+  
+  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());
+        }
+
+        // look to see if local core state changed
+        CoreState coreState = zkController.getCoreState(core.getName());
+        if (coreState != info.coreState) {
+          sb.append(" " + info.shortId + "_STATE=" + coreState);
+          info.coreState = coreState;
+        }
+      }
+    }
+
+
+    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
+    } else if (zkController != null) {
+      // if we don't have info about the core, then at least try to do core container
+      sb.append(" P").append(zkController.getHostPort());
+    }
+
+    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) {
+      CloudState cloudState = zkController.getCloudState();
+      if (info.cloudState != cloudState) {
+        // something has changed in the matrix...
+        sb.append(zkController.getBaseUrl() + " sees new CloudState:");
+      }
+    }
+    ***/
+    
+    return sb.toString();
+  }
+
+  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 appendMultiLineString(StringBuilder sb, String msg) {
+    int idx = msg.indexOf('\n');
+    if (idx < 0) {
+      sb.append(msg);
+      return;
+    }
+
+    int lastIdx = -1;
+    for (;;) {
+      if (idx < 0) {
+        sb.append(msg.substring(lastIdx+1));
+        break;
+      }
+      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<String>();
+  
+  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 (Throwable e) {
+          e.printStackTrace();
+        }
+      }
+    };
+    
+    th.start();
+    th.join();
+  }
+  
+
+  static class MyThreadGroup extends ThreadGroup implements TG {
+    public MyThreadGroup(String name) {
+      super(name);
+    }
+    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("InThread1");
+      }
+    };
+
+    Thread thread2 = new Thread() {
+      @Override
+      public void run() {
+        threadLocal.set("from thread2");
+        log.error("InThread2");
+      }
+    };
+
+    thread1.start();
+    thread2.start();
+    thread1.join();
+    thread2.join();    
+  }
+}

solr/core/src/java/org/apache/solr/cloud/ZkController.java

@@ -339,6 +339,10 @@ public final class ZkController {
   public String getHostName() {
     return hostName;
   }
+  
+  public String getHostPort() {
+    return localHostPort;
+  }
 
   public SolrZkClient getZkClient() {
     return zkClient;

solr/core/src/java/org/apache/solr/core/SolrCore.java

@@ -1532,20 +1532,28 @@ public final class SolrCore implements SolrInfoMBean {
     NamedList<Object> toLog = rsp.getToLog();
     // for back compat, we set these now just in case other code
     // are expecting them during handleRequest
-    toLog.add("webapp", req.getContext().get("webapp"));
+
+    // multiple webaps are no longer best practise
+    // toLog.add("webapp", req.getContext().get("webapp"));
+
     toLog.add("path", req.getContext().get("path"));
     toLog.add("params", "{" + req.getParamString() + "}");
     
     handler.handleRequest(req,rsp);
     setResponseHeaderValues(handler,req,rsp);
 
-    if (log.isInfoEnabled()) {
-      StringBuilder sb = new StringBuilder(logid);
+    if (log.isInfoEnabled() && toLog.size() > 0) {
+      StringBuilder sb = new StringBuilder();
       for (int i=0; i<toLog.size(); i++) {
         String name = toLog.getName(i);
         Object val = toLog.getVal(i);
-        sb.append(name).append("=").append(val).append(" ");
+        if ("path"==name || "params"==name) {    //equals OK here
+          sb.append(val).append(' ');
+        } else {
+          sb.append(name).append('=').append(val).append(' ');
+        }
       }
+
       log.info(sb.toString());
     }
 
@@ -1567,9 +1575,12 @@ public final class SolrCore implements SolrInfoMBean {
     }
     responseHeader.add("status",status);
     responseHeader.add("QTime",qtime);
-    rsp.getToLog().add("status",status);
-    rsp.getToLog().add("QTime",qtime);
-    
+
+    if (rsp.getToLog().size() > 0) {
+      rsp.getToLog().add("status",status);
+      rsp.getToLog().add("QTime",qtime);
+    }
+
     SolrParams params = req.getParams();
     if( params.getBool(CommonParams.HEADER_ECHO_HANDLER, false) ) {
       responseHeader.add("handler", handler.getName() );

solr/core/src/java/org/apache/solr/handler/component/SearchHandler.java

@@ -131,12 +131,12 @@ public class SearchHandler extends RequestHandlerBase implements SolrCoreAware ,
         dbgCmp = (DebugComponent) comp;
       } else {
         components.add(comp);
-        log.info("Adding  component:"+comp);
+        log.debug("Adding  component:"+comp);
       }
     }
     if (makeDebugLast == true && dbgCmp != null){
       components.add(dbgCmp);
-      log.info("Adding  debug component:" + dbgCmp);
+      log.debug("Adding  debug component:" + dbgCmp);
     }
     if(shfInfo ==null) {
       shardHandlerFactory = core.getCoreDescriptor().getCoreContainer().getShardHandlerFactory();

solr/core/src/java/org/apache/solr/search/SolrIndexSearcher.java

@@ -79,6 +79,7 @@ public class SolrIndexSearcher extends IndexSearcher implements Closeable,SolrIn
   private final SolrCore core;
   private final IndexSchema schema;
   private String indexDir;
+  private boolean debug = log.isDebugEnabled();
 
   private final String name;
   private long openTime = System.currentTimeMillis();
@@ -244,17 +245,20 @@ public class SolrIndexSearcher extends IndexSearcher implements Closeable,SolrIn
    * In particular, the underlying reader and any cache's in use are closed.
    */
   public void close() throws IOException {
-    if (cachingEnabled) {
-      StringBuilder sb = new StringBuilder();
-      sb.append("Closing ").append(name);
-      for (SolrCache cache : cacheList) {
-        sb.append("\n\t");
-        sb.append(cache);
+    if (debug) {
+      if (cachingEnabled) {
+        StringBuilder sb = new StringBuilder();
+        sb.append("Closing ").append(name);
+        for (SolrCache cache : cacheList) {
+          sb.append("\n\t");
+          sb.append(cache);
+        }
+        log.debug(sb.toString());
+      } else {
+        if (debug) log.debug("Closing " + name);
       }
-      log.info(sb.toString());
-    } else {
-      log.debug("Closing " + name);
     }
+
     core.getInfoRegistry().remove(name);
 
     // super.close();
@@ -1897,13 +1901,12 @@ public class SolrIndexSearcher extends IndexSearcher implements Closeable,SolrIn
    */
   public void warm(SolrIndexSearcher old) throws IOException {
     // Make sure this is first!  filters can help queryResults execute!
-    boolean logme = log.isInfoEnabled();
     long warmingStartTime = System.currentTimeMillis();
     // warm the caches in order...
     ModifiableSolrParams params = new ModifiableSolrParams();
     params.add("warming","true");
     for (int i=0; i<cacheList.length; i++) {
-      if (logme) log.info("autowarming " + this + " from " + old + "\n\t" + old.cacheList[i]);
+      if (debug) log.debug("autowarming " + this + " from " + old + "\n\t" + old.cacheList[i]);
 
 
       SolrQueryRequest req = new LocalSolrQueryRequest(core,params) {
@@ -1923,7 +1926,7 @@ public class SolrIndexSearcher extends IndexSearcher implements Closeable,SolrIn
         }
       }
 
-      if (logme) log.info("autowarming result for " + this + "\n\t" + this.cacheList[i]);
+      if (debug) log.debug("autowarming result for " + this + "\n\t" + this.cacheList[i]);
     }
     warmupTime = System.currentTimeMillis() - warmingStartTime;
   }

solr/core/src/java/org/apache/solr/update/PeerSync.java

@@ -184,6 +184,12 @@ public class PeerSync  {
 
     log.info(msg() + "START replicas=" + replicas + " nUpdates=" + nUpdates);
 
+    // TODO: does it ever make sense to allow sync when buffering or applying buffered?  Someone might request that we do it...
+    if (!(ulog.getState() == UpdateLog.State.ACTIVE || ulog.getState()==UpdateLog.State.REPLAYING)) {
+      log.error(msg() + "ERROR, update log not in ACTIVE or REPLAY state. " + ulog);
+      // return false;
+    }
+    
     if (debug) {
       if (startingVersions != null) {
         log.debug(msg() + "startingVersions=" + startingVersions.size() + " " + startingVersions);
@@ -396,7 +402,7 @@ public class PeerSync  {
   private boolean requestUpdates(ShardResponse srsp, List<Long> toRequest) {
     String replica = srsp.getShardRequest().shards[0];
 
-    log.info(msg() + "Requesting updates from " + replica + " versions=" + toRequest);
+    log.info(msg() + "Requesting updates from " + replica + "n=" + toRequest.size() + " versions=" + toRequest);
 
     // reuse our original request object
     ShardRequest sreq = srsp.getShardRequest();
@@ -426,6 +432,7 @@ public class PeerSync  {
 
     ModifiableSolrParams params = new ModifiableSolrParams();
     params.set(DistributedUpdateProcessor.SEEN_LEADER, true);
+params.set("peersync",true); // nocommit
     SolrQueryRequest req = new LocalSolrQueryRequest(uhandler.core, params);
     SolrQueryResponse rsp = new SolrQueryResponse();
 

solr/core/src/java/org/apache/solr/update/processor/LogUpdateProcessorFactory.java

@@ -46,7 +46,6 @@ import org.slf4j.LoggerFactory;
 public class LogUpdateProcessorFactory extends UpdateRequestProcessorFactory {
   
   int maxNumToLog = 10;
-  
   @Override
   public void init( final NamedList args ) {
     if( args != null ) {
@@ -191,6 +190,21 @@ class LogUpdateProcessor extends UpdateRequestProcessor {
     // be logged by SolrCore
     
     // if id lists were truncated, show how many more there were
+
+    NamedList<Object> stdLog = rsp.getToLog();
+
+    StringBuilder sb = new StringBuilder();
+    for (int i=0; i<stdLog.size(); i++) {
+      String name = stdLog.getName(i);
+      Object val = stdLog.getVal(i);
+      if ("path"==name || "params"==name) {    //equals OK here
+        sb.append(val).append(' ');
+      } else {
+        sb.append(name).append('=').append(val).append(' ');
+      }
+    }
+    stdLog.clear();   // make it so SolrCore.exec won't log this again
+
     if (adds != null && numAdds > maxNumToLog) {
       adds.add("... (" + numAdds + " adds)");
     }
@@ -198,7 +212,9 @@ class LogUpdateProcessor extends UpdateRequestProcessor {
       deletes.add("... (" + numDeletes + " deletes)");
     }
     long elapsed = rsp.getEndTime() - req.getStartTime();
-    log.info( ""+toLog + " 0 " + (elapsed) );
+
+    sb.append(toLog).append(" 0 ").append(elapsed);
+    log.info(sb.toString());
   }
 }
 

solr/core/src/java/org/apache/solr/update/processor/UpdateRequestProcessorFactory.java

@@ -39,6 +39,5 @@ public abstract class UpdateRequestProcessorFactory implements NamedListInitiali
     // could process the Node
   }
   
-  abstract public UpdateRequestProcessor getInstance( 
-      SolrQueryRequest req, SolrQueryResponse rsp, UpdateRequestProcessor next );
+  abstract public UpdateRequestProcessor getInstance(SolrQueryRequest req, SolrQueryResponse rsp, UpdateRequestProcessor next );
 }

solr/core/src/java/org/apache/solr/util/plugin/AbstractPluginLoader.java

@@ -139,7 +139,7 @@ public abstract class AbstractPluginLoader<T>
           String defaultStr = DOMUtil.getAttr(node,"default", null );
             
           T plugin = create(loader, name, className, node );
-          log.info("created " + ((name != null) ? name : "") + ": " + plugin.getClass().getName());
+          log.debug("created " + ((name != null) ? name : "") + ": " + plugin.getClass().getName());
           
           // Either initialize now or wait till everything has been registered
           if( preRegister ) {
@@ -209,7 +209,7 @@ public abstract class AbstractPluginLoader<T>
       String name = DOMUtil.getAttr(node, "name", requireName ? type : null);
       String className = DOMUtil.getAttr(node, "class", type);
       plugin = create(loader, name, className, node);
-      log.info("created " + name + ": " + plugin.getClass().getName());
+      log.debug("created " + name + ": " + plugin.getClass().getName());
 
       // Either initialize now or wait till everything has been registered
       if (preRegister) {

solr/solrj/src/java/org/apache/solr/common/util/NamedList.java

@@ -395,6 +395,11 @@ public class NamedList<T> implements Cloneable, Serializable, Iterable<Map.Entry
     return null;
   }
 
+
+  public void clear() {
+    nvPairs.clear();
+  }
+
   @Override
   public int hashCode() {
     return nvPairs.hashCode();