All Downloads are FREE. Search and download functionalities are using the official Maven repository.

org.apache.solr.SolrLogFormatter Maven / Gradle / Ivy

There is a newer version: 9.6.1
Show newest version
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 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 coreProps;
  }

  Map coreInfoMap = new WeakHashMap();    // TODO: use something that survives across a core reload?

  public Map 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 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 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 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();    
  }
}




© 2015 - 2024 Weber Informatics LLC | Privacy Policy