This is an automated email from the ASF dual-hosted git repository.
dsmiley pushed a commit to branch branch_9x
in repository https://gitbox.apache.org/repos/asf/solr.git
The following commit(s) were added to refs/heads/branch_9x by this push:
new 2a4a24c SOLR-14686: Logs: Remove log "[coreName]" in SolrCore which
is redundant with MDC (#517)
2a4a24c is described below
commit 2a4a24c8e62aeffd54e49f5370df56500b52cf83
Author: David Smiley <[email protected]>
AuthorDate: Fri Jan 21 10:40:12 2022 -0500
SOLR-14686: Logs: Remove log "[coreName]" in SolrCore which is redundant
with MDC (#517)
Also, ensured any problems in SolrCore.close has MDC info in logs.
---
solr/CHANGES.txt | 3 +
.../src/java/org/apache/solr/core/SolrCore.java | 72 ++++++++++------------
.../apache/solr/response/SolrQueryResponse.java | 10 ++-
.../org/apache/solr/rest/BaseSolrResource.java | 2 +-
.../apache/solr/update/DirectUpdateHandler2.java | 4 +-
.../processor/LogUpdateProcessorFactory.java | 2 +-
.../java/org/apache/solr/util/SolrLogPostTool.java | 5 ++
.../org/apache/solr/util/SolrLogPostToolTest.java | 34 +++++++---
8 files changed, 76 insertions(+), 56 deletions(-)
diff --git a/solr/CHANGES.txt b/solr/CHANGES.txt
index ed1caa7..56daf25 100644
--- a/solr/CHANGES.txt
+++ b/solr/CHANGES.txt
@@ -238,6 +238,9 @@ when told to. The admin UI now tells it to. (Nazerke
Seidan, David Smiley)
* SOLR-14916: Add split parameter to timeseries Streaming Expression (Joel
Bernstein)
+* SOLR-14686: Logs: Removed the "[corename]" prefix of some SolrCore logs that
has become redundant
+ with MDC. (David Smiley)
+
* SOLR-15884: Backup responses now use a map to return information instead of
a list (Houston Putman, Christine Poerschke)
Build
diff --git a/solr/core/src/java/org/apache/solr/core/SolrCore.java
b/solr/core/src/java/org/apache/solr/core/SolrCore.java
index eae94c9..d3604a2 100644
--- a/solr/core/src/java/org/apache/solr/core/SolrCore.java
+++ b/solr/core/src/java/org/apache/solr/core/SolrCore.java
@@ -194,7 +194,7 @@ public final class SolrCore implements SolrInfoBean,
Closeable {
private static final Logger slowLog =
LoggerFactory.getLogger(MethodHandles.lookup().lookupClass().getName() +
".SlowRequest"); //nowarn
private String name;
- private String logid; // used to show what name is set
+
/**
* A unique id to differentiate multiple instances of the same core
* If we reload a core, the name remains same , but the id will be new
@@ -519,23 +519,21 @@ public final class SolrCore implements SolrInfoBean,
Closeable {
}
@Override
+ public String toString() {
+ return super.toString() + " " + getName();
+ }
+
+ @Override
public String getName() {
return name;
}
+ /** Called to rename a core. Not called to initialize the name. */
public void setName(String v) {
- Objects.requireNonNull(v);
- boolean renamed = this.name != null && !this.name.equals(v);
- assert !renamed || coreDescriptor.getCloudDescriptor() == null : "Cores
are not renamed in SolrCloud";
- this.name = v;
- this.logid = "[" + v + "] "; // TODO remove; obsoleted by MDC
- if (renamed && coreMetricManager != null) {
- coreMetricManager.afterCoreRename();
- }
- }
-
- public String getLogId() {
- return this.logid;
+ assert this.name != null;
+ assert coreDescriptor.getCloudDescriptor() == null : "Cores are not
renamed in SolrCloud";
+ this.name = Objects.requireNonNull(v);
+ coreMetricManager.afterCoreRename();
}
/**
@@ -672,11 +670,11 @@ public final class SolrCore implements SolrInfoBean,
Closeable {
if ("firstSearcher".equals(event)) {
SolrEventListener obj = createEventListener(info);
firstSearcherListeners.add(obj);
- log.debug("[{}] Added SolrEventListener for firstSearcher: [{}]",
logid, obj);
+ log.debug("Added SolrEventListener for firstSearcher: [{}]", obj);
} else if ("newSearcher".equals(event)) {
SolrEventListener obj = createEventListener(info);
newSearcherListeners.add(obj);
- log.debug("[{}] Added SolrEventListener for newSearcher: [{}]", logid,
obj);
+ log.debug("Added SolrEventListener for newSearcher: [{}]", obj);
}
}
}
@@ -830,7 +828,7 @@ public final class SolrCore implements SolrInfoBean,
Closeable {
Directory dir = directoryFactory.get(indexDir, DirContext.DEFAULT,
lockType);
try {
if (isWriterLocked(dir)) {
- log.error("{}Solr index directory '{}' is locked (lockType={}).
Throwing exception.", logid,
+ log.error("Solr index directory '{}' is locked (lockType={}).
Throwing exception.",
indexDir, lockType);
throw new LockObtainFailedException(
"Index dir '" + indexDir + "' of core '" + name + "' is already
locked. " +
@@ -845,7 +843,7 @@ public final class SolrCore implements SolrInfoBean,
Closeable {
// Create the index if it doesn't exist.
if (!indexExists) {
- log.debug("{}Solr index directory '{}' doesn't exist. Creating new
index...", logid, indexDir);
+ log.debug("Solr index directory '{}' doesn't exist. Creating new
index...", indexDir);
SolrIndexWriter writer = null;
try {
writer = SolrIndexWriter.create(this, "SolrCore.initIndex", indexDir,
getDirectoryFactory(), true,
@@ -955,20 +953,15 @@ public final class SolrCore implements SolrInfoBean,
Closeable {
return createReloadedUpdateHandler(className, "Update Handler",
updateHandler);
}
- public SolrCore(CoreContainer coreContainer, CoreDescriptor cd, ConfigSet
configSet) {
- this(coreContainer, cd, configSet, null,
- null, null, null, false);
- }
-
public CoreContainer getCoreContainer() {
return coreContainer;
}
+ SolrCore(CoreContainer coreContainer, CoreDescriptor cd, ConfigSet
configSet) {
+ this(coreContainer, cd, configSet, null,
+ null, null, null, false);
+ }
- /**
- * Creates a new core and register it in the list of cores. If a core with
the
- * same name already exists, it will be stopped and replaced by this one.
- */
private SolrCore(CoreContainer coreContainer, CoreDescriptor coreDescriptor,
ConfigSet configSet,
String dataDir, UpdateHandler updateHandler,
IndexDeletionPolicyWrapper delPolicy, SolrCore prev,
boolean reload) {
@@ -980,7 +973,7 @@ public final class SolrCore implements SolrInfoBean,
Closeable {
this.coreContainer = coreContainer;
this.configSet = configSet;
this.coreDescriptor = Objects.requireNonNull(coreDescriptor,
"coreDescriptor cannot be null");
- setName(coreDescriptor.getName());
+ this.name = Objects.requireNonNull(coreDescriptor.getName());
coreProvider = new Provider(coreContainer, getName(), uniqueId);
this.solrConfig = configSet.getSolrConfig();
@@ -1010,7 +1003,7 @@ public final class SolrCore implements SolrInfoBean,
Closeable {
this.ulogDir = initUpdateLogDir(coreDescriptor);
if (log.isInfoEnabled()) {
- log.info("[{}] Opening new SolrCore at [{}], dataDir=[{}]", logid,
getInstancePath(), this.dataDir);
+ log.info("Opening new SolrCore at [{}], dataDir=[{}]",
getInstancePath(), this.dataDir);
}
checkVersionFieldExistsInSchema(schema, coreDescriptor);
@@ -1580,7 +1573,6 @@ public final class SolrCore implements SolrInfoBean,
Closeable {
*/
@Override
public void close() {
- MDCLoggingContext.clear(); // balance out open with close
int count = refCount.decrementAndGet();
if (count > 0) return; // close is called often, and only actually closes
if nothing is using it.
if (count < 0) {
@@ -1588,7 +1580,7 @@ public final class SolrCore implements SolrInfoBean,
Closeable {
assert false : "Too many closes on SolrCore";
return;
}
- log.info("{} CLOSING SolrCore {}", logid, this);
+ log.info("CLOSING SolrCore {}", this);
ExecutorUtil.shutdownAndAwaitTermination(coreAsyncTaskExecutor);
@@ -1728,6 +1720,8 @@ public final class SolrCore implements SolrInfoBean,
Closeable {
}
}
+ MDCLoggingContext.clear(); // balance out open with close
+
assert ObjectReleaseTracker.release(this);
}
@@ -2309,7 +2303,7 @@ public final class SolrCore implements SolrInfoBean,
Closeable {
newSearcherCounter.inc();
if (onDeckSearchers < 1) {
// should never happen... just a sanity check
- log.error("{}ERROR!!! onDeckSearchers is {}", logid,
onDeckSearchers);
+ log.error("ERROR!!! onDeckSearchers is {}", onDeckSearchers);
onDeckSearchers = 1; // reset
} else if (onDeckSearchers > maxWarmingSearchers) {
onDeckSearchers--;
@@ -2323,7 +2317,7 @@ public final class SolrCore implements SolrInfoBean,
Closeable {
}
continue; // go back to the top of the loop and retry
} else if (onDeckSearchers > 1) {
- log.warn("{}PERFORMANCE WARNING: Overlapping onDeckSearchers={}",
logid, onDeckSearchers);
+ log.warn("PERFORMANCE WARNING: Overlapping onDeckSearchers={}",
onDeckSearchers);
}
break; // I can now exit the loop and proceed to open a searcher
@@ -2480,7 +2474,7 @@ public final class SolrCore implements SolrInfoBean,
Closeable {
if (onDeckSearchers < 0) {
// sanity check... should never happen
- log.error("{}ERROR!!! onDeckSearchers after decrement={}", logid,
onDeckSearchers);
+ log.error("ERROR!!! onDeckSearchers after decrement={}",
onDeckSearchers);
onDeckSearchers = 0; // try and recover
}
// if we failed, we need to wake up at least one waiter to continue
the process
@@ -2578,7 +2572,7 @@ public final class SolrCore implements SolrInfoBean,
Closeable {
newSearcher.register(); // register subitems (caches)
if (log.isInfoEnabled()) {
- log.info("{} Registered new searcher autowarm time: {} ms", logid,
newSearcher.getWarmupTime());
+ log.info("Registered new searcher autowarm time: {} ms",
newSearcher.getWarmupTime());
}
} catch (Exception e) {
@@ -2596,7 +2590,7 @@ public final class SolrCore implements SolrInfoBean,
Closeable {
public void closeSearcher() {
- log.debug("{}Closing main searcher on request.", logid);
+ log.debug("Closing main searcher on request.");
synchronized (searcherLock) {
if (realtimeSearcher != null) {
realtimeSearcher.decref();
@@ -2614,7 +2608,7 @@ public final class SolrCore implements SolrInfoBean,
Closeable {
String msg = "Null Request Handler '" +
req.getParams().get(CommonParams.QT) + "'";
- log.warn("{}{}:{}", logid, msg, req);
+ log.warn("{}:{}", msg, req);
throw new SolrException(ErrorCode.BAD_REQUEST, msg);
}
@@ -2629,7 +2623,7 @@ public final class SolrCore implements SolrInfoBean,
Closeable {
*/
if (requestLog.isDebugEnabled() && rsp.getToLog().size() > 0) {
// log request at debug in case something goes wrong and we aren't able
to log later
- requestLog.debug(rsp.getToLogAsString(logid));
+ requestLog.debug(rsp.getToLogAsString());
}
// TODO: this doesn't seem to be working correctly and causes problems
with the example server and distrib (for example /spell)
@@ -2641,14 +2635,14 @@ public final class SolrCore implements SolrInfoBean,
Closeable {
if (rsp.getToLog().size() > 0) {
if (requestLog.isInfoEnabled()) {
- requestLog.info(rsp.getToLogAsString(logid));
+ requestLog.info(rsp.getToLogAsString());
}
/* slowQueryThresholdMillis defaults to -1 in SolrConfig -- not
enabled.*/
if (log.isWarnEnabled() && slowQueryThresholdMillis >= 0) {
final long qtime = (long) (req.getRequestTimer().getTime());
if (qtime >= slowQueryThresholdMillis) {
- slowLog.warn("slow: {}", rsp.getToLogAsString(logid));
+ slowLog.warn("slow: {}", rsp.getToLogAsString());
}
}
}
diff --git a/solr/core/src/java/org/apache/solr/response/SolrQueryResponse.java
b/solr/core/src/java/org/apache/solr/response/SolrQueryResponse.java
index bc4fb4d..cc47796 100644
--- a/solr/core/src/java/org/apache/solr/response/SolrQueryResponse.java
+++ b/solr/core/src/java/org/apache/solr/response/SolrQueryResponse.java
@@ -222,9 +222,13 @@ public class SolrQueryResponse {
return toLog;
}
- /** Returns a string of the form "logid name1=value1 name2=value2 ..." */
- public String getToLogAsString(String logid) {
- StringBuilder sb = new StringBuilder(logid);
+ public String getToLogAsString() {
+ return getToLogAsString("");
+ }
+
+ /** Returns a string of the form "prefix name1=value1 name2=value2 ..." */
+ public String getToLogAsString(String prefix) {
+ StringBuilder sb = new StringBuilder(prefix);
for (int i=0; i<toLog.size(); i++) {
if (sb.length() > 0) {
sb.append(' ');
diff --git a/solr/core/src/java/org/apache/solr/rest/BaseSolrResource.java
b/solr/core/src/java/org/apache/solr/rest/BaseSolrResource.java
index 11047ec..459fccf 100644
--- a/solr/core/src/java/org/apache/solr/rest/BaseSolrResource.java
+++ b/solr/core/src/java/org/apache/solr/rest/BaseSolrResource.java
@@ -106,7 +106,7 @@ public abstract class BaseSolrResource {
addDeprecatedWarning();
if (log.isInfoEnabled() && solrResponse.getToLog().size() > 0) {
- log.info(solrResponse.getToLogAsString(solrCore.getLogId()));
+ log.info(solrResponse.getToLogAsString());
}
}
diff --git
a/solr/core/src/java/org/apache/solr/update/DirectUpdateHandler2.java
b/solr/core/src/java/org/apache/solr/update/DirectUpdateHandler2.java
index acc7c67..94b1c4a 100644
--- a/solr/core/src/java/org/apache/solr/update/DirectUpdateHandler2.java
+++ b/solr/core/src/java/org/apache/solr/update/DirectUpdateHandler2.java
@@ -208,9 +208,7 @@ public class DirectUpdateHandler2 extends UpdateHandler
implements SolrCoreState
}
private void deleteAll() throws IOException {
- if (log.isInfoEnabled()) {
- log.info("{} REMOVING ALL DOCUMENTS FROM INDEX", core.getLogId());
- }
+ log.info("REMOVING ALL DOCUMENTS FROM INDEX");
RefCounted<IndexWriter> iw = solrCoreState.getIndexWriter(core);
try {
iw.get().deleteAll();
diff --git
a/solr/core/src/java/org/apache/solr/update/processor/LogUpdateProcessorFactory.java
b/solr/core/src/java/org/apache/solr/update/processor/LogUpdateProcessorFactory.java
index a3eb260..59db7d9 100644
---
a/solr/core/src/java/org/apache/solr/update/processor/LogUpdateProcessorFactory.java
+++
b/solr/core/src/java/org/apache/solr/update/processor/LogUpdateProcessorFactory.java
@@ -209,7 +209,7 @@ public class LogUpdateProcessorFactory extends
UpdateRequestProcessorFactory imp
}
private String getLogStringAndClearRspToLog() {
- StringBuilder sb = new
StringBuilder(rsp.getToLogAsString(req.getCore().getLogId()));
+ StringBuilder sb = new StringBuilder(rsp.getToLogAsString());
rsp.getToLog().clear(); // make it so SolrCore.exec won't log this
again
diff --git a/solr/core/src/java/org/apache/solr/util/SolrLogPostTool.java
b/solr/core/src/java/org/apache/solr/util/SolrLogPostTool.java
index ec9cfcc..bf5f753 100644
--- a/solr/core/src/java/org/apache/solr/util/SolrLogPostTool.java
+++ b/solr/core/src/java/org/apache/solr/util/SolrLogPostTool.java
@@ -381,6 +381,11 @@ public class SolrLogPostTool {
}
private String parseNewSearcherCore(String line) {
+ String xCore = parseCore(line);
+ if (xCore != null) {
+ return xCore;
+ }
+ // pre Solr 9
char[] ca = {']'};
String parts[] = line.split("\\[");
if(parts.length > 3) {
diff --git a/solr/core/src/test/org/apache/solr/util/SolrLogPostToolTest.java
b/solr/core/src/test/org/apache/solr/util/SolrLogPostToolTest.java
index e518cd5..5be6469 100644
--- a/solr/core/src/test/org/apache/solr/util/SolrLogPostToolTest.java
+++ b/solr/core/src/test/org/apache/solr/util/SolrLogPostToolTest.java
@@ -18,23 +18,35 @@ package org.apache.solr.util;
import java.io.BufferedReader;
import java.io.StringReader;
+import java.util.ArrayList;
import java.util.Collection;
import java.util.List;
-import java.util.ArrayList;
-
import org.apache.solr.SolrTestCaseJ4;
import org.apache.solr.common.SolrInputDocument;
import org.apache.solr.common.SolrInputField;
import org.apache.solr.util.SolrLogPostTool.LogRecordReader;
-
+import org.junit.BeforeClass;
import org.junit.Test;
public class SolrLogPostToolTest extends SolrTestCaseJ4 {
+ private static boolean solr9Format;
+
+ @BeforeClass
+ public static void beforeClass() {
+ solr9Format = random().nextBoolean();
+ System.out.println("Solr 9 Format: " + solr9Format);
+ }
+
+ private String sometimesSolr9Format(String record) {
+ // pull out bracketed core name that is redundant with MDC -- see
SOLR-14686
+ return solr9Format ? record.replaceFirst("\\[[a-zA-Z0-9_]+\\] +", "") :
record;
+ }
@Test
public void testQueryRecord() throws Exception{
- String record = "2019-12-09 15:05:11.931 INFO (qtp2103763750-21) [c:logs4
s:shard1 r:core_node2 x:logs4_shard1_replica_n1] o.a.s.c.S.Request
[logs4_shard1_replica_n1] webapp=/solr path=/select
params={q=*:*&_=1575835181759&shards.purpose=36&isShard=true&wt=javabin&distrib=false}
hits=234868 status=0 QTime=8\n";
+ String record = sometimesSolr9Format(
+ "2019-12-09 15:05:11.931 INFO (qtp2103763750-21) [c:logs4 s:shard1
r:core_node2 x:logs4_shard1_replica_n1] o.a.s.c.S.Request
[logs4_shard1_replica_n1] webapp=/solr path=/select
params={q=*:*&_=1575835181759&shards.purpose=36&isShard=true&wt=javabin&distrib=false}
hits=234868 status=0 QTime=8\n");
List<SolrInputDocument> docs = readDocs(record);
assertEquals(docs.size(), 1);
SolrInputDocument doc = docs.get(0);
@@ -85,7 +97,8 @@ public class SolrLogPostToolTest extends SolrTestCaseJ4 {
// values are received.
@Test
public void testRecordsFirstInstanceOfSingleValuedParams() throws Exception {
- final String record = "2019-12-09 15:05:01.931 INFO (qtp2103763750-21)
[c:logs4 s:shard1 r:core_node2 x:logs4_shard1_replica_n1] o.a.s.c.S.Request
[logs4_shard1_replica_n1] webapp=/solr path=/select
params={q=*:*&q=inStock:true&_=1575835181759&shards.purpose=36&isShard=true&wt=javabin&wt=xml&distrib=false}
hits=234868 status=0 QTime=8\n";
+ final String record = sometimesSolr9Format(
+ "2019-12-09 15:05:01.931 INFO (qtp2103763750-21) [c:logs4 s:shard1
r:core_node2 x:logs4_shard1_replica_n1] o.a.s.c.S.Request
[logs4_shard1_replica_n1] webapp=/solr path=/select
params={q=*:*&q=inStock:true&_=1575835181759&shards.purpose=36&isShard=true&wt=javabin&wt=xml&distrib=false}
hits=234868 status=0 QTime=8\n");
List<SolrInputDocument> docs = readDocs(record);
assertEquals(docs.size(), 1);
@@ -100,7 +113,8 @@ public class SolrLogPostToolTest extends SolrTestCaseJ4 {
@Test
public void testRTGRecord() throws Exception {
- final String record = "2020-03-19 20:00:30.845 INFO (qtp1635378213-20354)
[c:logs4 s:shard8 r:core_node63 x:logs4_shard8_replica_n60] o.a.s.c.S.Request
[logs4_shard8_replica_n60] webapp=/solr path=/get
params={qt=/get&_stateVer_=logs4:104&ids=id1&ids=id2&ids=id3&wt=javabin&version=2}
status=0 QTime=61";
+ final String record = sometimesSolr9Format(
+ "2020-03-19 20:00:30.845 INFO (qtp1635378213-20354) [c:logs4 s:shard8
r:core_node63 x:logs4_shard8_replica_n60] o.a.s.c.S.Request
[logs4_shard8_replica_n60] webapp=/solr path=/get
params={qt=/get&_stateVer_=logs4:104&ids=id1&ids=id2&ids=id3&wt=javabin&version=2}
status=0 QTime=61");
List<SolrInputDocument> docs = readDocs(record);
assertEquals(docs.size(), 1);
@@ -121,8 +135,9 @@ public class SolrLogPostToolTest extends SolrTestCaseJ4 {
@Test
public void testUpdateRecords() throws Exception{
- String record = "2019-12-25 20:38:23.498 INFO (qtp2103763750-126)
[c:logs3 s:shard1 r:core_node2 x:logs3_shard1_replica_n1]
o.a.s.u.p.LogUpdateProcessorFactory [logs3_shard1_replica_n1] webapp=/solr
path=/update
params={commitWithin=1000&overwrite=true&wt=json&_=1577306114481}{deleteByQuery=*:*
(-1653925534487281664)} 0 11\n" +
- "2019-12-25 20:42:13.411 INFO (qtp2103763750-303)
[c:logs5 s:shard1 r:core_node2 x:logs5_shard1_replica_n1]
o.a.s.u.p.LogUpdateProcessorFactory [logs5_shard1_replica_n1] webapp=/solr
path=/update
params={commitWithin=1000&overwrite=true&wt=json&_=1577306114481}{delete=[03bbe975-728a-4df8-aa25-fe25049dc0ef
(-1653925775577972736)]} 0 1\n";
+ String record = sometimesSolr9Format(
+ "2019-12-25 20:38:23.498 INFO (qtp2103763750-126) [c:logs3 s:shard1
r:core_node2 x:logs3_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory
[logs3_shard1_replica_n1] webapp=/solr path=/update
params={commitWithin=1000&overwrite=true&wt=json&_=1577306114481}{deleteByQuery=*:*
(-1653925534487281664)} 0 11\n" +
+ "2019-12-25 20:42:13.411 INFO (qtp2103763750-303)
[c:logs5 s:shard1 r:core_node2 x:logs5_shard1_replica_n1]
o.a.s.u.p.LogUpdateProcessorFactory [logs5_shard1_replica_n1] webapp=/solr
path=/update
params={commitWithin=1000&overwrite=true&wt=json&_=1577306114481}{delete=[03bbe975-728a-4df8-aa25-fe25049dc0ef
(-1653925775577972736)]} 0 1\n");
List<SolrInputDocument> docs = readDocs(record);
assertEquals(docs.size(), 2);
SolrInputDocument doc = docs.get(0);
@@ -279,7 +294,8 @@ public class SolrLogPostToolTest extends SolrTestCaseJ4 {
@Test
public void testNewSearcher() throws Exception{
- String record = "2019-12-16 19:00:23.931 INFO
(searcherExecutor-66-thread-1) [ ] o.a.s.c.SolrCore
[production_cv_month_201912_shard35_replica_n1] Registered new searcher
Searcher@16ef5fac[production_cv_month_201912_shard35_replica_n1] ...";
+ String record = sometimesSolr9Format(
+ "2019-12-16 19:00:23.931 INFO (searcherExecutor-66-thread-1) [
x:production_cv_month_201912_shard35_replica_n1] o.a.s.c.SolrCore
[production_cv_month_201912_shard35_replica_n1] Registered new searcher
Searcher@16ef5fac[production_cv_month_201912_shard35_replica_n1] ...");
List<SolrInputDocument> docs = readDocs(record);
assertEquals(docs.size(), 1);
SolrInputDocument doc = docs.get(0);
