enhanced logging (to be used in self-enhancement reports)

This commit is contained in:
Michael Peter Christen committed 2026-07-05 09:19:46 +02:00
1 parent 28c6e01bcd
commit 9e5958ab0e
12 files changed
+290 -135

No files matched your search

+30 -5
View File
@@ -83,6 +83,13 @@ public final class TextParser {
private static final Parser genericIdiom = new genericParser(); private static final Parser genericIdiom = new genericParser();
private static String locationLogMeta(final DigestURL location, final String mimeType) {
return "host=" + (location == null ? "unknown" : location.getHost()) +
" url=" + (location == null ? "unknown" : location.toNormalform(true)) +
" ext=" + (location == null ? "" : MultiProtocolURL.getFileExtension(location.getFileName())) +
" mime=" + (mimeType == null ? "" : mimeType);
}
/** A generic XML parser instance */ /** A generic XML parser instance */
private static final Parser genericXMLIdiom = new GenericXMLParser(); private static final Parser genericXMLIdiom = new GenericXMLParser();
@@ -262,7 +269,7 @@ public final class TextParser {
final Date lastModified final Date lastModified
) throws Parser.Failure { ) throws Parser.Failure {
if (AbstractParser.log.isFine()) { if (AbstractParser.log.isFine()) {
AbstractParser.log.fine("Parsing '" + location + "' from byte-array, applying only the generic parser"); AbstractParser.log.fine("event=parse.plan subsystem=parser source=byte-array mode=generic-only " + locationLogMeta(location, mimeType));
} }
mimeType = normalizeMimeType(mimeType); mimeType = normalizeMimeType(mimeType);
final Set<Parser> idioms = new HashSet<>(); final Set<Parser> idioms = new HashSet<>();
@@ -286,14 +293,14 @@ public final class TextParser {
final long maxBytes, final long maxBytes,
final Date lastModified final Date lastModified
) throws Parser.Failure { ) throws Parser.Failure {
if (AbstractParser.log.isFine()) AbstractParser.log.fine("Parsing '" + location + "' from stream"); if (AbstractParser.log.isFine()) AbstractParser.log.fine("event=parse.plan subsystem=parser source=stream contentLength=" + contentLength + " maxLinks=" + maxLinks + " maxBytes=" + maxBytes + " " + locationLogMeta(location, mimeType));
mimeType = normalizeMimeType(mimeType); mimeType = normalizeMimeType(mimeType);
Set<Parser> idioms = null; Set<Parser> idioms = null;
try { try {
idioms = parsers(location, mimeType); idioms = parsers(location, mimeType);
} catch (final Parser.Failure e) { } catch (final Parser.Failure e) {
final String errorMsg = "Parser Failure for extension '" + MultiProtocolURL.getFileExtension(location.getFileName()) + "' or mimetype '" + mimeType + "': " + e.getMessage(); final String errorMsg = "Parser Failure for extension '" + MultiProtocolURL.getFileExtension(location.getFileName()) + "' or mimetype '" + mimeType + "': " + e.getMessage();
AbstractParser.log.warn(errorMsg); AbstractParser.log.warn("event=parse.select subsystem=parser result=failure reason=unsupported " + locationLogMeta(location, mimeType));
throw new Parser.Failure(errorMsg, location); throw new Parser.Failure(errorMsg, location);
} }
assert !idioms.isEmpty() : "no parsers applied for url " + location.toNormalform(true); assert !idioms.isEmpty() : "no parsers applied for url " + location.toNormalform(true);
@@ -334,6 +341,7 @@ public final class TextParser {
/* Loop on parser : they are supposed to be sorted in order to start with the most specific and end with the most generic */ /* Loop on parser : they are supposed to be sorted in order to start with the most specific and end with the most generic */
for(final Parser parser : idioms) { for(final Parser parser : idioms) {
final long parserStart = System.currentTimeMillis();
/* Wrap in a CloseShieldInputStream to prevent SAX parsers closing the sourceStream /* Wrap in a CloseShieldInputStream to prevent SAX parsers closing the sourceStream
* and so let us eventually reuse the same opened stream with other parsers on parser failure */ * and so let us eventually reuse the same opened stream with other parsers on parser failure */
CloseShieldInputStream nonCloseInputStream = CloseShieldInputStream.wrap(markableStream); CloseShieldInputStream nonCloseInputStream = CloseShieldInputStream.wrap(markableStream);
@@ -342,6 +350,9 @@ public final class TextParser {
return parseSource(location, mimeType, parser, charset, defaultValency, valencySwitchTagNames, scraper, timezoneOffset, return parseSource(location, mimeType, parser, charset, defaultValency, valencySwitchTagNames, scraper, timezoneOffset,
nonCloseInputStream, maxLinks, maxBytes, lastModified); nonCloseInputStream, maxLinks, maxBytes, lastModified);
} catch (final Parser.Failure e) { } catch (final Parser.Failure e) {
AbstractParser.log.warn("event=parse.parser subsystem=parser result=fallback parser=\"" + parser.getName() +
"\" reason=" + e.getMessage() + " durationMs=" + (System.currentTimeMillis() - parserStart) +
" " + locationLogMeta(location, mimeType));
/* Try to reset the marked stream. If the failed parser has consumed too many bytes : /* Try to reset the marked stream. If the failed parser has consumed too many bytes :
* too bad, the marks is invalid and process fails now with an IOException */ * too bad, the marks is invalid and process fails now with an IOException */
markableStream.reset(); markableStream.reset();
@@ -362,12 +373,15 @@ public final class TextParser {
final Document maindoc = gzipParser.createMainDocument(location, mimeType, charset, gzParser); final Document maindoc = gzipParser.createMainDocument(location, mimeType, charset, gzParser);
try { try {
final long gzipFallbackStart = System.currentTimeMillis();
final Document[] docs = gzParser.parseCompressedInputStream(location, final Document[] docs = gzParser.parseCompressedInputStream(location,
charset, timezoneOffset, depth, charset, timezoneOffset, depth,
nonCloseInputStream, maxLinks, maxBytes); nonCloseInputStream, maxLinks, maxBytes);
if (docs != null) { if (docs != null) {
maindoc.addSubDocuments(docs); maindoc.addSubDocuments(docs);
} }
AbstractParser.log.info("event=parse.parser subsystem=parser result=gzip-fallback-success parser=\"" + parser.getName() +
"\" durationMs=" + (System.currentTimeMillis() - gzipFallbackStart) + " " + locationLogMeta(location, mimeType));
return new Document[] { maindoc }; return new Document[] { maindoc };
} catch(final Exception e1) { } catch(final Exception e1) {
/* Try again to reset the marked stream if the failed parser has not consumed too many bytes */ /* Try again to reset the marked stream if the failed parser has not consumed too many bytes */
@@ -566,7 +580,7 @@ public final class TextParser {
final Date lastModified final Date lastModified
) throws Parser.Failure { ) throws Parser.Failure {
final String fileExt = MultiProtocolURL.getFileExtension(location.getFileName()); final String fileExt = MultiProtocolURL.getFileExtension(location.getFileName());
if (AbstractParser.log.isFine()) AbstractParser.log.fine("Parsing " + location + " with mimeType '" + mimeType + "' and file extension '" + fileExt + "' from byte[]"); if (AbstractParser.log.isFine()) AbstractParser.log.fine("event=parse.plan subsystem=parser source=byte-array parserCount=" + parsers.size() + " bytes=" + sourceArray.length + " maxLinks=" + maxLinks + " maxBytes=" + maxBytes + " " + locationLogMeta(location, mimeType));
final String documentCharset = htmlParser.patchCharsetEncoding(charset); final String documentCharset = htmlParser.patchCharsetEncoding(charset);
assert !parsers.isEmpty(); assert !parsers.isEmpty();
@@ -576,6 +590,7 @@ public final class TextParser {
Thread.currentThread().setName("parsing + " + location.toString()); // set a name to get the address in Thread Dump Thread.currentThread().setName("parsing + " + location.toString()); // set a name to get the address in Thread Dump
for (final Parser parser: parsers) { for (final Parser parser: parsers) {
if (MemoryControl.request(sourceArray.length * 6, false)) { if (MemoryControl.request(sourceArray.length * 6, false)) {
final long parserStart = System.currentTimeMillis();
ByteArrayInputStream bis; ByteArrayInputStream bis;
if (mimeType.equals("text/plain") && parser.getName().equals("HTML Parser")) { if (mimeType.equals("text/plain") && parser.getName().equals("HTML Parser")) {
// a hack to simulate html files .. is needed for NOLOAD queues. This throws their data into virtual text/plain messages. // a hack to simulate html files .. is needed for NOLOAD queues. This throws their data into virtual text/plain messages.
@@ -594,6 +609,9 @@ public final class TextParser {
docs = parser.parse(location, mimeType, documentCharset, defaultValency, valencySwitchTagNames, scraper, timezoneOffset, bis); docs = parser.parse(location, mimeType, documentCharset, defaultValency, valencySwitchTagNames, scraper, timezoneOffset, bis);
} }
} catch (final Parser.Failure e) { } catch (final Parser.Failure e) {
AbstractParser.log.warn("event=parse.parser subsystem=parser result=fallback parser=\"" + parser.getName() +
"\" reason=" + e.getMessage() + " durationMs=" + (System.currentTimeMillis() - parserStart) +
" " + locationLogMeta(location, mimeType));
if(parser instanceof gzipParser && e.getCause() instanceof GZIPOpeningStreamException && if(parser instanceof gzipParser && e.getCause() instanceof GZIPOpeningStreamException &&
(parsers.size() == 1 || (parsers.size() == 2 && parsers.contains(genericIdiom)))) { (parsers.size() == 1 || (parsers.size() == 2 && parsers.contains(genericIdiom)))) {
/* The gzip parser failed directly when opening the content stream : before falling back to the generic parser, /* The gzip parser failed directly when opening the content stream : before falling back to the generic parser,
@@ -610,6 +628,7 @@ public final class TextParser {
final Document maindoc = gzipParser.createMainDocument(location, mimeType, charset, gzParser); final Document maindoc = gzipParser.createMainDocument(location, mimeType, charset, gzParser);
try { try {
final long gzipFallbackStart = System.currentTimeMillis();
docs = gzParser.parseCompressedInputStream(location, docs = gzParser.parseCompressedInputStream(location,
charset, timezoneOffset, depth, charset, timezoneOffset, depth,
bis, maxLinks, maxBytes); bis, maxLinks, maxBytes);
@@ -617,6 +636,8 @@ public final class TextParser {
maindoc.addSubDocuments(docs); maindoc.addSubDocuments(docs);
} }
docs = new Document[] { maindoc }; docs = new Document[] { maindoc };
AbstractParser.log.info("event=parse.parser subsystem=parser result=gzip-fallback-success parser=\"" + parser.getName() +
"\" durationMs=" + (System.currentTimeMillis() - gzipFallbackStart) + " " + locationLogMeta(location, mimeType));
break; break;
} catch(final Parser.Failure e1) { } catch(final Parser.Failure e1) {
failedParser.put(parser, e1); failedParser.put(parser, e1);
@@ -627,6 +648,9 @@ public final class TextParser {
failedParser.put(parser, e); failedParser.put(parser, e);
} }
} catch (final Exception e) { } catch (final Exception e) {
AbstractParser.log.warn("event=parse.parser subsystem=parser result=fallback parser=\"" + parser.getName() +
"\" reason=" + e.getMessage() + " durationMs=" + (System.currentTimeMillis() - parserStart) +
" " + locationLogMeta(location, mimeType));
failedParser.put(parser, new Parser.Failure(e.getMessage(), location)); failedParser.put(parser, new Parser.Failure(e.getMessage(), location));
//log.logWarning("tried parser '" + parser.getName() + "' to parse " + location.toNormalform(true, false) + " but failed: " + e.getMessage(), e); //log.logWarning("tried parser '" + parser.getName() + "' to parse " + location.toNormalform(true, false) + " but failed: " + e.getMessage(), e);
} finally { } finally {
@@ -649,7 +673,8 @@ public final class TextParser {
} }
String failedParsers = ""; String failedParsers = "";
for (final Map.Entry<Parser, Parser.Failure> error: failedParser.entrySet()) { for (final Map.Entry<Parser, Parser.Failure> error: failedParser.entrySet()) {
AbstractParser.log.warn("tried parser '" + error.getKey().getName() + "' to parse " + location.toNormalform(true) + " but failed: " + error.getValue().getMessage(), error.getValue()); AbstractParser.log.warn("event=parse.parser subsystem=parser result=failure parser=\"" + error.getKey().getName() +
"\" reason=" + error.getValue().getMessage() + " " + locationLogMeta(location, mimeType), error.getValue());
failedParsers += error.getKey().getName() + " "; failedParsers += error.getKey().getName() + " ";
} }
throw new Parser.Failure("All parser failed: " + failedParsers, location); throw new Parser.Failure("All parser failed: " + failedParsers, location);
+22 -8
View File
@@ -115,9 +115,20 @@ public final class hello {
// we easily know the caller's IP: // we easily know the caller's IP:
final String userAgent = header.get(HeaderFramework.USER_AGENT, "<unknown>"); final String userAgent = header.get(HeaderFramework.USER_AGENT, "<unknown>");
sb.peers.peerActions.setUserAgent(clientip, userAgent); sb.peers.peerActions.setUserAgent(clientip, userAgent);
final Set<String> reportedips = remoteSeed.getIPs(); final Set<String> reportedips = remoteSeed.getIPs();
final String reportedPeerType = remoteSeed.get(Seed.PEERTYPE, Seed.PEERTYPE_JUNIOR); final String reportedPeerType = remoteSeed.get(Seed.PEERTYPE, Seed.PEERTYPE_JUNIOR);
//final double clientversion = remoteSeed.getVersion(); final boolean reportedIPv4 = Seed.hasIPv4(reportedips);
final boolean reportedIPv6 = Seed.hasIPv6(reportedips);
if (reportedIPv6 && !reportedIPv4) {
Network.log.info("hello/server: ipv6-only remote seed observed peer='" + remoteSeed.getName()
+ "', hash=" + remoteSeed.hash + ", clientAddressFamily=" + Seed.addressFamily(clientip)
+ ", reportedAddressProfile=" + Seed.addressProfile(reportedips));
} else if (reportedIPv6 && Network.log.isFine()) {
Network.log.fine("hello/server: dual-stack remote seed observed peer='" + remoteSeed.getName()
+ "', hash=" + remoteSeed.hash + ", clientAddressFamily=" + Seed.addressFamily(clientip)
+ ", reportedAddressProfile=" + Seed.addressProfile(reportedips));
}
//final double clientversion = remoteSeed.getVersion();
if (remoteSeed.getPort() == sb.peers.mySeed().getPort()) { if (remoteSeed.getPort() == sb.peers.mySeed().getPort()) {
if (sb.peers.mySeed().clash(reportedips)) { if (sb.peers.mySeed().clash(reportedips)) {
@@ -167,11 +178,14 @@ public final class hello {
for (final String reportedip: reportedips) { for (final String reportedip: reportedips) {
final int partialtimeout = ((int) (callbackStart + totalTimeout - System.currentTimeMillis())) / callbackRemain; // bad hack until a concurrent version is implemented final int partialtimeout = ((int) (callbackStart + totalTimeout - System.currentTimeMillis())) / callbackRemain; // bad hack until a concurrent version is implemented
if (partialtimeout <= 0) break; if (partialtimeout <= 0) break;
//ConcurrentLog.info("**hello-DEBUG**", "reportedip = " + reportedip + " is handled"); //ConcurrentLog.info("**hello-DEBUG**", "reportedip = " + reportedip + " is handled");
if (Seed.isProperIP(reportedip)) { if (Seed.isProperIP(reportedip)) {
//ConcurrentLog.info("**hello-DEBUG**", "starting callback to reportedip = " + reportedip + ", timeout = " + partialtimeout); if (Network.log.isFine()) Network.log.fine("hello/server: backping candidate peer='" + remoteSeed.getName()
prop.put("yourip", reportedip); + "', address=" + reportedip + ", addressFamily=" + Seed.addressFamily(reportedip)
remoteSeed.setIP(reportedip); + ", remainingCandidates=" + callbackRemain);
//ConcurrentLog.info("**hello-DEBUG**", "starting callback to reportedip = " + reportedip + ", timeout = " + partialtimeout);
prop.put("yourip", reportedip);
remoteSeed.setIP(reportedip);
time = System.currentTimeMillis(); time = System.currentTimeMillis();
try { try {
MultiProtocolURL remoteBaseURL = remoteSeed.getPublicMultiprotocolURL(reportedip, preferHttps); MultiProtocolURL remoteBaseURL = remoteSeed.getPublicMultiprotocolURL(reportedip, preferHttps);
@@ -13,6 +13,8 @@ import org.eclipse.jetty.server.Request;
import org.eclipse.jetty.server.Server; import org.eclipse.jetty.server.Server;
import org.eclipse.jetty.server.handler.HandlerWrapper; import org.eclipse.jetty.server.handler.HandlerWrapper;
import net.yacy.cora.util.ConcurrentLog;
public class CrashProtectionHandler extends HandlerWrapper implements Handler, HandlerContainer { public class CrashProtectionHandler extends HandlerWrapper implements Handler, HandlerContainer {
public CrashProtectionHandler() { public CrashProtectionHandler() {
@@ -32,6 +34,8 @@ public class CrashProtectionHandler extends HandlerWrapper implements Handler, H
try { try {
super.handle(target, baseRequest, request, response); super.handle(target, baseRequest, request, response);
} catch (Exception e) { } catch (Exception e) {
ConcurrentLog.severe("HTTP", "event=http.request subsystem=http result=exception method=" + request.getMethod() +
" target=" + target + " status=500 reason=" + e.getMessage());
// handle all we can // handle all we can
writeResponse(request, response, e); writeResponse(request, response, e);
baseRequest.setHandled(true); baseRequest.setHandled(true);
@@ -169,11 +169,11 @@ public class YaCyDefaultServlet extends HttpServlet {
} else { } else {
this._resourceBase = Resource.newResource(sb.getConfig(SwitchboardConstants.HTROOT_PATH, SwitchboardConstants.HTROOT_PATH_DEFAULT)); //default this._resourceBase = Resource.newResource(sb.getConfig(SwitchboardConstants.HTROOT_PATH, SwitchboardConstants.HTROOT_PATH_DEFAULT)); //default
} }
} catch (final IOException e) { } catch (final IOException e) {
ConcurrentLog.severe("FILEHANDLER", "YaCyDefaultServlet: resource base (htRootPath) missing"); ConcurrentLog.severe("FILEHANDLER", "event=http.resource subsystem=http result=missing-resource-base reason=" + e.getMessage());
ConcurrentLog.logException(e); ConcurrentLog.logException(e);
throw new UnavailableException(e.toString()); throw new UnavailableException(e.toString());
} }
if (ConcurrentLog.isFine("FILEHANDLER")) { if (ConcurrentLog.isFine("FILEHANDLER")) {
ConcurrentLog.fine("FILEHANDLER","YaCyDefaultServlet: resource base = " + this._resourceBase); ConcurrentLog.fine("FILEHANDLER","YaCyDefaultServlet: resource base = " + this._resourceBase);
} }
@@ -351,11 +351,12 @@ public class YaCyDefaultServlet extends HttpServlet {
} }
} }
} }
} catch (final IllegalArgumentException e) { } catch (final IllegalArgumentException e) {
ConcurrentLog.logException(e); ConcurrentLog.warn("FILEHANDLER", "event=http.resource subsystem=http result=illegal-argument path=" + pathInContext +
if (!response.isCommitted()) { " reason=" + e.getMessage());
response.sendError(HttpServletResponse.SC_INTERNAL_SERVER_ERROR, e.getMessage()); if (!response.isCommitted()) {
} response.sendError(HttpServletResponse.SC_INTERNAL_SERVER_ERROR, e.getMessage());
}
} finally { } finally {
if (resource != null) { if (resource != null) {
resource.close(); resource.close();
@@ -406,7 +407,9 @@ public class YaCyDefaultServlet extends HttpServlet {
} }
return buffer.toString(StandardCharsets.UTF_8.name()); return buffer.toString(StandardCharsets.UTF_8.name());
} catch (final IOException e) { } catch (final IOException e) {
ConcurrentLog.warn("FILEHANDLER", "Failed to read POST body: " + e.getMessage()); ConcurrentLog.warn("FILEHANDLER", "event=http.request subsystem=http result=body-read-failure method=" + request.getMethod() +
" contentType=" + request.getContentType() + " contentLength=" + request.getContentLengthLong() +
" reason=" + e.getMessage());
return null; return null;
} }
} }
+44 -31
View File
@@ -205,10 +205,13 @@ public class Network
SwitchboardConstants.NETWORK_PROTOCOL_HTTPS_PREFERRED, SwitchboardConstants.NETWORK_PROTOCOL_HTTPS_PREFERRED,
SwitchboardConstants.NETWORK_PROTOCOL_HTTPS_PREFERRED_DEFAULT); SwitchboardConstants.NETWORK_PROTOCOL_HTTPS_PREFERRED_DEFAULT);
for (final String ip: this.seed.getIPs()) { for (final String ip: this.seed.getIPs()) {
try { try {
MultiProtocolURL targetBaseURL = this.seed.getPublicMultiprotocolURL(ip, preferHttps); if (log.isFine()) log.fine("publish: attempting " + this.seed.get(Seed.PEERTYPE, Seed.PEERTYPE_SENIOR) + " peer '"
result = Protocol.hello(Network.this.sb.peers.mySeed(), Network.this.sb.peers.peerActions, targetBaseURL, this.seed.hash); + this.seed.getName() + "' address=" + ip + ", addressFamily=" + Seed.addressFamily(ip)
if (result == null && targetBaseURL.isHTTPS()) { + ", seedAddressProfile=" + Seed.addressProfile(this.seed.getIPs()));
MultiProtocolURL targetBaseURL = this.seed.getPublicMultiprotocolURL(ip, preferHttps);
result = Protocol.hello(Network.this.sb.peers.mySeed(), Network.this.sb.peers.peerActions, targetBaseURL, this.seed.hash);
if (result == null && targetBaseURL.isHTTPS()) {
/* Failed with https : retry with http on the same address */ /* Failed with https : retry with http on the same address */
targetBaseURL = this.seed.getPublicMultiprotocolURL(ip, false); targetBaseURL = this.seed.getPublicMultiprotocolURL(ip, false);
result = Protocol.hello(Network.this.sb.peers.mySeed(), Network.this.sb.peers.peerActions, result = Protocol.hello(Network.this.sb.peers.mySeed(), Network.this.sb.peers.peerActions,
@@ -222,22 +225,28 @@ public class Network
Network.this.sb.peers.updateConnected(this.seed); Network.this.sb.peers.updateConnected(this.seed);
} }
} }
if(result == null) { if(result == null) {
// no or wrong response, delete that address // no or wrong response, delete that address
final String cause = "peer ping to peer resulted in error response (added < 0)"; final String cause = "peer ping to peer resulted in error response (added < 0)";
log.info("publish: disconnected " + this.seed.get(Seed.PEERTYPE, Seed.PEERTYPE_SENIOR) + " peer '" + this.seed.getName() + "' from " + this.seed.getIPs() + ": " + cause); log.info("publish: disconnected " + this.seed.get(Seed.PEERTYPE, Seed.PEERTYPE_SENIOR) + " peer '" + this.seed.getName()
Network.this.sb.peers.peerActions.interfaceDeparture(this.seed, ip); + "' address=" + ip + ", addressFamily=" + Seed.addressFamily(ip)
continue; + ", seedAddressProfile=" + Seed.addressProfile(this.seed.getIPs()) + ": " + cause);
} Network.this.sb.peers.peerActions.interfaceDeparture(this.seed, ip);
} catch(final MalformedURLException e) { continue;
final String cause = "malformed peer URL"; }
log.info("publish: disconnected " + this.seed.get(Seed.PEERTYPE, Seed.PEERTYPE_SENIOR) + " peer '" + this.seed.getName() + "' from " + this.seed.getIPs() + ": " + cause); } catch(final MalformedURLException e) {
Network.this.sb.peers.peerActions.interfaceDeparture(this.seed, ip); final String cause = "malformed peer URL";
continue; log.info("publish: disconnected " + this.seed.get(Seed.PEERTYPE, Seed.PEERTYPE_SENIOR) + " peer '" + this.seed.getName()
} + "' address=" + ip + ", addressFamily=" + Seed.addressFamily(ip)
// success! we have published our peer to a senior peer + ", seedAddressProfile=" + Seed.addressProfile(this.seed.getIPs()) + ": " + cause);
// update latest news from the other peer Network.this.sb.peers.peerActions.interfaceDeparture(this.seed, ip);
log.info("publish: handshaked "+ this.seed.get(Seed.PEERTYPE, Seed.PEERTYPE_SENIOR) + " peer '" + this.seed.getName() + "' at " + this.seed.getIPs()); continue;
}
// success! we have published our peer to a senior peer
// update latest news from the other peer
log.info("publish: handshaked "+ this.seed.get(Seed.PEERTYPE, Seed.PEERTYPE_SENIOR) + " peer '" + this.seed.getName()
+ "' address=" + ip + ", addressFamily=" + Seed.addressFamily(ip)
+ ", seedAddressProfile=" + Seed.addressProfile(this.seed.getIPs()));
// check if seed's lastSeen has been updated // check if seed's lastSeen has been updated
final Seed newSeed = Network.this.sb.peers.getConnected(this.seed.hash); final Seed newSeed = Network.this.sb.peers.getConnected(this.seed.hash);
if ( newSeed != null ) { if ( newSeed != null ) {
@@ -278,7 +287,8 @@ public class Network
} catch (final Exception e ) { } catch (final Exception e ) {
ConcurrentLog.logException(e); ConcurrentLog.logException(e);
log.severe( log.severe(
"publishThread: error with target seed " + this.seed.toString() + ": " + e.getMessage(), "publishThread: error with target seed " + this.seed.toString()
+ ", seedAddressProfile=" + Seed.addressProfile(this.seed.getIPs()) + ": " + e.getMessage(),
e); e);
} }
} }
@@ -375,17 +385,20 @@ public class Network
final Set<String> ips = seed.getIPs(); final Set<String> ips = seed.getIPs();
if(ips.isEmpty()) { if(ips.isEmpty()) {
/* This should not happen : seeds db maintains only seeds with at least one IP */ /* This should not happen : seeds db maintains only seeds with at least one IP */
log.warn("Peer " + seed.getName() + "has no known IP address"); log.warn("publish: peer '" + seed.getName() + "' has no known IP address, seedAddressProfile=" + Seed.addressProfile(ips));
} else { } else {
final String ip = ips.iterator().next(); final String ip = ips.iterator().next();
final String address = seed.getPublicAddress(ip); final String address = seed.getPublicAddress(ip);
if ( log.isFine() ) log.fine("HELLO #" + i + " to peer '" + seed.getName() + "' at " + address); // debug if ( log.isFine() ) log.fine("HELLO #" + i + " to peer '" + seed.getName() + "' at " + address); // debug
final String seederror = seed.isProper(false); final String seederror = seed.isProper(false);
if ( (address == null) || (seederror != null) ) { if ( (address == null) || (seederror != null) ) {
// we don't like that address, delete it log.info("publish: skipping peer '" + seed.getName() + "' before publish thread, address="
this.sb.peers.peerActions.interfaceDeparture(seed, ip); + ip + ", addressFamily=" + Seed.addressFamily(ip) + ", publicAddress=" + address
} else { + ", seedError=" + seederror + ", seedAddressProfile=" + Seed.addressProfile(ips));
// we don't like that address, delete it
this.sb.peers.peerActions.interfaceDeparture(seed, ip);
} else {
// starting a new publisher thread // starting a new publisher thread
final publishThread t = new publishThread(Network.publishThreadGroup, seed); final publishThread t = new publishThread(Network.publishThreadGroup, seed);
t.start(); t.start();
+17 -10
View File
@@ -516,16 +516,23 @@ public final class Protocol {
// partitions : number of remote peers that are asked (for evaluation of QPM) // partitions : number of remote peers that are asked (for evaluation of QPM)
// duetime : maximum time that a peer should spent to create a result // duetime : maximum time that a peer should spent to create a result
final long timestamp = System.currentTimeMillis(); final long timestamp = System.currentTimeMillis();
event.addExpectedRemoteReferences(count); event.addExpectedRemoteReferences(count);
SearchResult result = null; SearchResult result = null;
for (String ip: target.getIPs()) { final boolean localClash = target.clash(event.peers.mySeed().getIPs());
//if (ip.indexOf(':') >= 0) System.out.println("Search target: IPv6: " + ip); if (localClash) {
final String targetBaseURL; Network.log.info("remote search: target peer '" + target.getName() + "'/" + target.hash
if (target.clash(event.peers.mySeed().getIPs())) { + " clashes with local peer addresses; using localhost, targetAddressProfile="
targetBaseURL = "http://localhost:" + event.peers.mySeed().getPort(); + Seed.addressProfile(target.getIPs()) + ", localAddressProfile="
} else { + Seed.addressProfile(event.peers.mySeed().getIPs()));
targetBaseURL = target.getPublicURL(ip, }
for (String ip: target.getIPs()) {
//if (ip.indexOf(':') >= 0) System.out.println("Search target: IPv6: " + ip);
final String targetBaseURL;
if (localClash) {
targetBaseURL = "http://localhost:" + event.peers.mySeed().getPort();
} else {
targetBaseURL = target.getPublicURL(ip,
Switchboard.getSwitchboard().getConfigBool(SwitchboardConstants.REMOTESEARCH_HTTPS_PREFERRED, Switchboard.getSwitchboard().getConfigBool(SwitchboardConstants.REMOTESEARCH_HTTPS_PREFERRED,
SwitchboardConstants.REMOTESEARCH_HTTPS_PREFERRED_DEFAULT)); SwitchboardConstants.REMOTESEARCH_HTTPS_PREFERRED_DEFAULT));
} }
+29
View File
@@ -448,6 +448,35 @@ public class Seed implements Cloneable, Comparable<Seed>, Comparator<Seed>
return false; return false;
} }
public static String addressFamily(final String ip) {
final String normalizedIP = Domains.chopZoneID(ip);
if (normalizedIP == null || normalizedIP.isEmpty()) return "unknown";
return normalizedIP.indexOf(':') >= 0 ? "ipv6" : "ipv4";
}
public static String addressProfile(final Set<String> ips) {
if (ips == null || ips.isEmpty()) return "total=0,ipv4=0,ipv6=0";
int ipv4 = 0;
int ipv6 = 0;
for (final String ip: ips) {
if ("ipv6".equals(addressFamily(ip))) ipv6++;
else if ("ipv4".equals(addressFamily(ip))) ipv4++;
}
return "total=" + ips.size() + ",ipv4=" + ipv4 + ",ipv6=" + ipv6;
}
public static boolean hasIPv4(final Set<String> ips) {
if (ips == null) return false;
for (final String ip: ips) if ("ipv4".equals(addressFamily(ip))) return true;
return false;
}
public static boolean hasIPv6(final Set<String> ips) {
if (ips == null) return false;
for (final String ip: ips) if ("ipv6".equals(addressFamily(ip))) return true;
return false;
}
private static boolean sameIP(final String left, final String right) { private static boolean sameIP(final String left, final String right) {
final String normalizedLeft = Domains.chopZoneID(left); final String normalizedLeft = Domains.chopZoneID(left);
final String normalizedRight = Domains.chopZoneID(right); final String normalizedRight = Domains.chopZoneID(right);
+6 -1
View File
@@ -244,7 +244,12 @@ public class Transmission {
// get possibly newer target Info // get possibly newer target Info
final Seed newTarget = Transmission.this.seeds.get(this.dhtTarget.hash); final Seed newTarget = Transmission.this.seeds.get(this.dhtTarget.hash);
if (newTarget != null) { if (newTarget != null) {
if (this.dhtTarget.clash(newTarget.getIPs())) { final boolean targetStillMatches = this.dhtTarget.clash(newTarget.getIPs());
Transmission.this.log.info("Transfer failed target address comparison target=" + this.dhtTarget.hash
+ "/" + this.dhtTarget.getName() + ", oldAddressProfile="
+ Seed.addressProfile(this.dhtTarget.getIPs()) + ", currentAddressProfile="
+ Seed.addressProfile(newTarget.getIPs()) + ", targetStillMatches=" + targetStillMatches);
if (targetStillMatches) {
newTarget.setFlagAcceptRemoteIndex(false); newTarget.setFlagAcceptRemoteIndex(false);
Transmission.this.seeds.updateConnected(newTarget); Transmission.this.seeds.updateConnected(newTarget);
} else { } else {
@@ -99,9 +99,19 @@ public final class LoaderDispatcher {
} }
@SuppressWarnings("unchecked") @SuppressWarnings("unchecked")
public HashSet<String> getSupportedProtocols() { public HashSet<String> getSupportedProtocols() {
return (HashSet<String>) this.supportedProtocols.clone(); return (HashSet<String>) this.supportedProtocols.clone();
} }
private static String requestLogMeta(final Request request, final DigestURL url) {
final String profile = request == null ? null : request.profileHandle();
return "protocol=" + (url == null ? "unknown" : url.getProtocol()) +
" host=" + (url == null ? "unknown" : url.getHost()) +
" url=" + (url == null ? "unknown" : url.toNormalform(true)) +
" ext=" + (url == null ? "" : net.yacy.cora.document.id.MultiProtocolURL.getFileExtension(url.getFileName())) +
" depth=" + (request == null ? -1 : request.depth()) +
" profile=" + (profile == null ? "" : profile);
}
/** /**
* generate a request object * generate a request object
@@ -169,12 +179,12 @@ public final class LoaderDispatcher {
if (check != null && cacheStrategy != CacheStrategy.NOCACHE) { if (check != null && cacheStrategy != CacheStrategy.NOCACHE) {
// a loading process is going on for that url // a loading process is going on for that url
//ConcurrentLog.info("LoaderDispatcher", "waiting for " + request.url().toNormalform(true)); //ConcurrentLog.info("LoaderDispatcher", "waiting for " + request.url().toNormalform(true));
final long t = System.currentTimeMillis(); final long t = System.currentTimeMillis();
try { check.tryAcquire(5, TimeUnit.SECONDS);} catch (final InterruptedException e) {} try { check.tryAcquire(5, TimeUnit.SECONDS);} catch (final InterruptedException e) {}
ConcurrentLog.info("LoaderDispatcher", "waited " + (System.currentTimeMillis() - t) + " ms for " + request.url().toNormalform(true)); ConcurrentLog.info("LoaderDispatcher", "event=loader.wait subsystem=crawler durationMs=" + (System.currentTimeMillis() - t) + " " + requestLogMeta(request, request.url()));
// now the process may have terminated and we run a normal loading // now the process may have terminated and we run a normal loading
// which may be successful faster because of a cache hit // which may be successful faster because of a cache hit
} }
this.loaderSteering.put(request.url(), new Semaphore(0)); this.loaderSteering.put(request.url(), new Semaphore(0));
try { try {
@@ -208,11 +218,12 @@ public final class LoaderDispatcher {
final String host = url.getHost(); final String host = url.getHost();
final CrawlProfile crawlProfile = request.profileHandle() == null ? null : this.sb.crawler.get(UTF8.getBytes(request.profileHandle())); final CrawlProfile crawlProfile = request.profileHandle() == null ? null : this.sb.crawler.get(UTF8.getBytes(request.profileHandle()));
// check if url is in blacklist // check if url is in blacklist
if (blacklistType != null && host != null && Switchboard.urlBlacklist.isListed(blacklistType, host.toLowerCase(Locale.ROOT), url.getFile())) { if (blacklistType != null && host != null && Switchboard.urlBlacklist.isListed(blacklistType, host.toLowerCase(Locale.ROOT), url.getFile())) {
this.sb.crawlQueues.errorURL.push(request.url(), request.depth(), crawlProfile, FailCategory.FINAL_LOAD_CONTEXT, "url in blacklist", -1); LoaderDispatcher.log.warn("event=loader.reject subsystem=crawler reason=blacklist blacklistType=" + blacklistType + " " + requestLogMeta(request, url));
throw new IOException("DISPATCHER Rejecting URL '" + request.url().toString() + "'. URL is in blacklist.$"); this.sb.crawlQueues.errorURL.push(request.url(), request.depth(), crawlProfile, FailCategory.FINAL_LOAD_CONTEXT, "url in blacklist", -1);
} throw new IOException("DISPATCHER Rejecting URL '" + request.url().toString() + "'. URL is in blacklist.$");
}
// check if we have the page in the cache // check if we have the page in the cache
Response response = this.loadFromCache(request, cacheStrategy, agent, url, crawlProfile); Response response = this.loadFromCache(request, cacheStrategy, agent, url, crawlProfile);
@@ -221,10 +232,11 @@ public final class LoaderDispatcher {
} }
// check case where we want results from the cache exclusively, and never from the Internet (offline mode) // check case where we want results from the cache exclusively, and never from the Internet (offline mode)
if (cacheStrategy == CacheStrategy.CACHEONLY) { if (cacheStrategy == CacheStrategy.CACHEONLY) {
// we had a chance to get the content from the cache .. its over. We don't have it. // we had a chance to get the content from the cache .. its over. We don't have it.
throw new IOException("cache only strategy"); LoaderDispatcher.log.info("event=loader.reject subsystem=crawler reason=cacheonly-miss cacheStrategy=" + cacheStrategy + " " + requestLogMeta(request, url));
} throw new IOException("cache only strategy");
}
// now forget about the cache, nothing there. Try to load the content from the Internet // now forget about the cache, nothing there. Try to load the content from the Internet
@@ -250,12 +262,16 @@ public final class LoaderDispatcher {
} else { } else {
throw new IOException("Unsupported protocol '" + protocol + "' in url " + url); throw new IOException("Unsupported protocol '" + protocol + "' in url " + url);
} }
if (response == null) { if (response == null) {
throw new IOException("no response (NULL) for url " + url); LoaderDispatcher.log.warn("event=loader.response subsystem=crawler result=null " + requestLogMeta(request, url));
} throw new IOException("no response (NULL) for url " + url);
if (response.getContent() == null) { }
throw new IOException("empty response (code " + response.getStatus() + ") for url " + url.toNormalform(true)); if (response.getContent() == null) {
} final ResponseHeader responseHeader = response.getResponseHeader();
LoaderDispatcher.log.warn("event=loader.response subsystem=crawler result=empty status=" +
(responseHeader == null ? -1 : responseHeader.getStatusCode()) + " " + requestLogMeta(request, url));
throw new IOException("empty response (code " + response.getStatus() + ") for url " + url.toNormalform(true));
}
// we got something. Now check if we want to store that to the cache // we got something. Now check if we want to store that to the cache
// first check looks if we want to store the content to the cache // first check looks if we want to store the content to the cache
@@ -320,32 +336,32 @@ public final class LoaderDispatcher {
// check which caching strategy shall be used // check which caching strategy shall be used
if (cacheStrategy == CacheStrategy.IFEXIST || cacheStrategy == CacheStrategy.CACHEONLY) { if (cacheStrategy == CacheStrategy.IFEXIST || cacheStrategy == CacheStrategy.CACHEONLY) {
// well, just take the cache and don't care about freshness of the content // well, just take the cache and don't care about freshness of the content
final byte[] content = Cache.getContent(url.hash()); final byte[] content = Cache.getContent(url.hash());
if (content != null) { if (content != null) {
LoaderDispatcher.log.info("cache hit/useall for: " + url.toNormalform(true)); LoaderDispatcher.log.info("event=loader.cache subsystem=crawler result=hit mode=useall bytes=" + content.length + " " + requestLogMeta(request, url));
response.setContent(content); response.setContent(content);
return response; return response;
} }
} }
// now the cacheStrategy must be CACHE_STRATEGY_IFFRESH, that means we should do a proxy freshness test // now the cacheStrategy must be CACHE_STRATEGY_IFFRESH, that means we should do a proxy freshness test
//assert cacheStrategy == CacheStrategy.IFFRESH : "cacheStrategy = " + cacheStrategy; //assert cacheStrategy == CacheStrategy.IFFRESH : "cacheStrategy = " + cacheStrategy;
if (response.isFreshForProxy()) { if (response.isFreshForProxy()) {
final byte[] content = Cache.getContent(url.hash()); final byte[] content = Cache.getContent(url.hash());
if (content != null) { if (content != null) {
LoaderDispatcher.log.info("cache hit/fresh for: " + url.toNormalform(true)); LoaderDispatcher.log.info("event=loader.cache subsystem=crawler result=hit mode=fresh bytes=" + content.length + " " + requestLogMeta(request, url));
response.setContent(content); response.setContent(content);
return response; return response;
} }
} }
LoaderDispatcher.log.info("cache hit/stale for: " + url.toNormalform(true)); LoaderDispatcher.log.info("event=loader.cache subsystem=crawler result=stale " + requestLogMeta(request, url));
/* Cached content can not be used : we return a null response to ensure callers will detect no cache response is available */ /* Cached content can not be used : we return a null response to ensure callers will detect no cache response is available */
response = null; response = null;
} else if (cachedResponse != null) { } else if (cachedResponse != null) {
LoaderDispatcher.log.warn("HTCACHE contained response header, but not content for url " + url.toNormalform(true)); LoaderDispatcher.log.warn("event=loader.cache subsystem=crawler result=header-without-content " + requestLogMeta(request, url));
} }
} }
return response; return response;
} }
/** /**
@@ -366,11 +382,12 @@ public final class LoaderDispatcher {
final String host = url.getHost(); final String host = url.getHost();
final CrawlProfile crawlProfile = request.profileHandle() == null ? null : this.sb.crawler.get(UTF8.getBytes(request.profileHandle())); final CrawlProfile crawlProfile = request.profileHandle() == null ? null : this.sb.crawler.get(UTF8.getBytes(request.profileHandle()));
// check if url is in blacklist // check if url is in blacklist
if (blacklistType != null && host != null && Switchboard.urlBlacklist.isListed(blacklistType, host.toLowerCase(Locale.ROOT), url.getFile())) { if (blacklistType != null && host != null && Switchboard.urlBlacklist.isListed(blacklistType, host.toLowerCase(Locale.ROOT), url.getFile())) {
this.sb.crawlQueues.errorURL.push(request.url(), request.depth(), crawlProfile, FailCategory.FINAL_LOAD_CONTEXT, "url in blacklist", -1); LoaderDispatcher.log.warn("event=loader.reject subsystem=crawler reason=blacklist blacklistType=" + blacklistType + " stream=true " + requestLogMeta(request, url));
throw new IOException("DISPATCHER Rejecting URL '" + request.url().toString() + "'. URL is in blacklist.$"); this.sb.crawlQueues.errorURL.push(request.url(), request.depth(), crawlProfile, FailCategory.FINAL_LOAD_CONTEXT, "url in blacklist", -1);
} throw new IOException("DISPATCHER Rejecting URL '" + request.url().toString() + "'. URL is in blacklist.$");
}
// check if we have the page in the cache // check if we have the page in the cache
final Response cachedResponse = this.loadFromCache(request, cacheStrategy, agent, url, crawlProfile); final Response cachedResponse = this.loadFromCache(request, cacheStrategy, agent, url, crawlProfile);
@@ -379,10 +396,11 @@ public final class LoaderDispatcher {
} }
// check case where we want results from the cache exclusively, and never from the Internet (offline mode) // check case where we want results from the cache exclusively, and never from the Internet (offline mode)
if (cacheStrategy == CacheStrategy.CACHEONLY) { if (cacheStrategy == CacheStrategy.CACHEONLY) {
// we had a chance to get the content from the cache .. its over. We don't have it. // we had a chance to get the content from the cache .. its over. We don't have it.
throw new IOException("cache only strategy"); LoaderDispatcher.log.info("event=loader.reject subsystem=crawler reason=cacheonly-miss stream=true cacheStrategy=" + cacheStrategy + " " + requestLogMeta(request, url));
} throw new IOException("cache only strategy");
}
// now forget about the cache, nothing there. Try to load the content from the Internet // now forget about the cache, nothing there. Try to load the content from the Internet
@@ -504,11 +522,11 @@ public final class LoaderDispatcher {
check.tryAcquire(5, TimeUnit.SECONDS); check.tryAcquire(5, TimeUnit.SECONDS);
} catch (final InterruptedException e) { } catch (final InterruptedException e) {
} }
ConcurrentLog.info("LoaderDispatcher", ConcurrentLog.info("LoaderDispatcher",
"waited " + (System.currentTimeMillis() - t) + " ms for " + request.url().toNormalform(true)); "event=loader.wait subsystem=crawler stream=true durationMs=" + (System.currentTimeMillis() - t) + " " + requestLogMeta(request, request.url()));
// now the process may have terminated and we run a normal loading // now the process may have terminated and we run a normal loading
// which may be successful faster because of a cache hit // which may be successful faster because of a cache hit
} }
this.loaderSteering.put(request.url(), new Semaphore(0)); this.loaderSteering.put(request.url(), new Semaphore(0));
try { try {
+16 -1
View File
@@ -325,8 +325,11 @@ public final class Fulltext {
final long t = System.currentTimeMillis(); final long t = System.currentTimeMillis();
if (this.lastCommit + 10000 > t) return; if (this.lastCommit + 10000 > t) return;
this.lastCommit = t; this.lastCommit = t;
final long start = System.currentTimeMillis();
this.getDefaultConnector().commit(softCommit); this.getDefaultConnector().commit(softCommit);
if (this.writeWebgraph) this.getWebgraphConnector().commit(softCommit); if (this.writeWebgraph) this.getWebgraphConnector().commit(softCommit);
ConcurrentLog.info("Fulltext", "event=solr.commit subsystem=index softCommit=" + softCommit +
" writeWebgraph=" + this.writeWebgraph + " durationMs=" + (System.currentTimeMillis() - start));
} }
/** /**
@@ -375,24 +378,36 @@ public final class Fulltext {
if (connector == null || connector.isClosed()) return; if (connector == null || connector.isClosed()) return;
final String id = (String) doc.getFieldValue(CollectionSchema.id.getSolrFieldName()); final String id = (String) doc.getFieldValue(CollectionSchema.id.getSolrFieldName());
final String url = (String) doc.getFieldValue(CollectionSchema.sku.getSolrFieldName()); final String url = (String) doc.getFieldValue(CollectionSchema.sku.getSolrFieldName());
final String host = (String) doc.getFieldValue(CollectionSchema.host_s.getSolrFieldName());
final Object httpStatus = doc.getFieldValue(CollectionSchema.httpstatus_i.getSolrFieldName());
assert url != null && url.length() < 30000; assert url != null && url.length() < 30000;
ConcurrentLog.info("Fulltext", "indexing: " + id + " " + url); final long start = System.currentTimeMillis();
try { try {
connector.add(doc); connector.add(doc);
} catch (final SolrException e) { } catch (final SolrException e) {
ConcurrentLog.warn("Fulltext", "event=index.document subsystem=index result=failure id=" + id +
" url=" + url + " host=" + host + " status=" + httpStatus + " reason=" + e.getMessage() +
" durationMs=" + (System.currentTimeMillis() - start));
throw new IOException(e.getMessage(), e); throw new IOException(e.getMessage(), e);
} }
ConcurrentLog.info("Fulltext", "event=index.document subsystem=index result=queued id=" + id +
" url=" + url + " host=" + host + " status=" + httpStatus + " durationMs=" + (System.currentTimeMillis() - start));
if (MemoryControl.shortStatus()) this.clearCaches(); if (MemoryControl.shortStatus()) this.clearCaches();
} }
public void putEdges(final Collection<SolrInputDocument> edges) throws IOException { public void putEdges(final Collection<SolrInputDocument> edges) throws IOException {
if (!this.useWebgraph()) return; if (!this.useWebgraph()) return;
if (edges == null || edges.size() == 0) return; if (edges == null || edges.size() == 0) return;
final long start = System.currentTimeMillis();
try { try {
this.getWebgraphConnector().add(edges); this.getWebgraphConnector().add(edges);
} catch (final SolrException e) { } catch (final SolrException e) {
ConcurrentLog.warn("Fulltext", "event=index.webgraph subsystem=index result=failure count=" + edges.size() +
" reason=" + e.getMessage() + " durationMs=" + (System.currentTimeMillis() - start));
throw new IOException(e.getMessage(), e); throw new IOException(e.getMessage(), e);
} }
ConcurrentLog.info("Fulltext", "event=index.webgraph subsystem=index result=queued count=" + edges.size() +
" durationMs=" + (System.currentTimeMillis() - start));
if (MemoryControl.shortStatus()) this.clearCaches(); if (MemoryControl.shortStatus()) this.clearCaches();
} }
+19 -3
View File
@@ -700,6 +700,7 @@ public final class SearchEvent implements ScoreMapUpdatesListener {
this.remote_rwi_stored.addAndGet(fullResource); this.remote_rwi_stored.addAndGet(fullResource);
this.remote_rwi_peerCount.incrementAndGet(); this.remote_rwi_peerCount.incrementAndGet();
} }
final String queryString = this.query.getQueryGoal().getQueryString(false);
long timer = System.currentTimeMillis(); long timer = System.currentTimeMillis();
// normalize entries // normalize entries
@@ -729,12 +730,20 @@ public final class SearchEvent implements ScoreMapUpdatesListener {
pollloop: while ( true ) { pollloop: while ( true ) {
remaining = timeout - System.currentTimeMillis(); remaining = timeout - System.currentTimeMillis();
if (remaining <= 0) { if (remaining <= 0) {
ConcurrentLog.warn("SearchEvent", "terminated 'add' loop before poll time-out = " + remaining + ", decodedEntries.size = " + decodedEntries.size()); ConcurrentLog.warn("SearchEvent", "event=search.rwi.add subsystem=search result=timeout phase=before-poll local=" + local +
" queryId=" + this.query.id(true) + " contentDomain=" + this.query.contentdom +
" query=\"" + queryString + "\"" +
" remainingMs=" + remaining + " decodedQueueSize=" + decodedEntries.size() +
" fullResource=" + fullResource + " maxtimeMs=" + maxtime);
break; break;
} }
iEntry = decodedEntries.poll(remaining, TimeUnit.MILLISECONDS); iEntry = decodedEntries.poll(remaining, TimeUnit.MILLISECONDS);
if (iEntry == null) { if (iEntry == null) {
ConcurrentLog.warn("SearchEvent", "terminated 'add' loop after poll time-out = " + remaining + ", decodedEntries.size = " + decodedEntries.size()); ConcurrentLog.warn("SearchEvent", "event=search.rwi.add subsystem=search result=timeout phase=poll local=" + local +
" queryId=" + this.query.id(true) + " contentDomain=" + this.query.contentdom +
" query=\"" + queryString + "\"" +
" remainingMs=" + remaining + " decodedQueueSize=" + decodedEntries.size() +
" fullResource=" + fullResource + " maxtimeMs=" + maxtime);
break pollloop; break pollloop;
} }
if (iEntry == WordReferenceVars.poison) { if (iEntry == WordReferenceVars.poison) {
@@ -829,9 +838,16 @@ public final class SearchEvent implements ScoreMapUpdatesListener {
successcounter++; successcounter++;
} }
if (System.currentTimeMillis() >= timeout) ConcurrentLog.warn("SearchEvent", "rwi normalization ended with timeout = " + maxtime); if (System.currentTimeMillis() >= timeout) ConcurrentLog.warn("SearchEvent", "event=search.rwi.normalization subsystem=search result=timeout local=" + local +
" queryId=" + this.query.id(true) + " contentDomain=" + this.query.contentdom +
" query=\"" + queryString + "\"" +
" count=" + successcounter + " fullResource=" + fullResource + " maxtimeMs=" + maxtime);
} catch (final InterruptedException e ) { } catch (final InterruptedException e ) {
ConcurrentLog.warn("SearchEvent", "event=search.rwi.add subsystem=search result=interrupted local=" + local +
" queryId=" + this.query.id(true) + " contentDomain=" + this.query.contentdom +
" query=\"" + queryString + "\"" +
" count=" + successcounter + " fullResource=" + fullResource + " maxtimeMs=" + maxtime);
} }
//if ((query.neededResults() > 0) && (container.size() > query.neededResults())) remove(true, true); //if ((query.neededResults() > 0) && (container.size() > query.neededResults())) remove(true, true);
@@ -270,7 +270,8 @@ public final class TemplateEngine {
try{ try{
num=Integer.parseInt(pattern.get(patternKey)); // Key contains the iteration number as string num=Integer.parseInt(pattern.get(patternKey)); // Key contains the iteration number as string
}catch(final NumberFormatException e){ }catch(final NumberFormatException e){
ConcurrentLog.logException(e); ConcurrentLog.warn("TEMPLATE", "event=template.pattern subsystem=http result=invalid-number servlet=" + servletname +
" patternKey=" + patternKey + " reason=" + e.getMessage());
num=0; num=0;
} }
} }
@@ -288,7 +289,8 @@ public final class TemplateEngine {
}//for }//for
structure.append(open_endtag).append(multi_key).append(close_tagn); structure.append(open_endtag).append(multi_key).append(close_tagn);
} else {//transferUntil } else {//transferUntil
ConcurrentLog.severe("TEMPLATE", "No Close Key found for #{"+UTF8.String(multi_key)+"}#" + " in " + servletname); //prefix here? ConcurrentLog.severe("TEMPLATE", "event=template.pattern subsystem=http result=missing-close type=multi servlet=" + servletname +
" key=" + UTF8.String(multi_key)); //prefix here?
} }
} }
@@ -331,7 +333,8 @@ public final class TemplateEngine {
if (byName) { if (byName) {
transferUntil(pis, keyStream, appendBytes(PP, patternName, null, null)); transferUntil(pis, keyStream, appendBytes(PP, patternName, null, null));
if(pis.available()==0){ if(pis.available()==0){
ConcurrentLog.severe("TEMPLATE", "Bad Key-Value pair in #()# construct: key=\"" + patternKey + "\", value=\"" + UTF8.String(patternName) + "\" in " + servletname); ConcurrentLog.severe("TEMPLATE", "event=template.pattern subsystem=http result=bad-key-value type=alternative servlet=" + servletname +
" key=" + patternKey + " value=" + UTF8.String(patternName));
final byte[] sb = structure.getBytes(); final byte[] sb = structure.getBytes();
structure.close(); structure.close();
text.close(); text.close();
@@ -343,7 +346,8 @@ public final class TemplateEngine {
structure.append(writeTemplate(servletname, pis2, out, pattern, newPrefix(prefix,key))); structure.append(writeTemplate(servletname, pis2, out, pattern, newPrefix(prefix,key)));
transferUntil(pis, keyStream, appendBytes(hash_brackopen_slash, key, brackclose_hash, null)); transferUntil(pis, keyStream, appendBytes(hash_brackopen_slash, key, brackclose_hash, null));
if(pis.available()==0){ if(pis.available()==0){
ConcurrentLog.severe("TEMPLATE", "No Close Key found for #("+UTF8.String(key)+")# (by Name) in " + servletname); ConcurrentLog.severe("TEMPLATE", "event=template.pattern subsystem=http result=missing-close type=alternative-by-name servlet=" + servletname +
" key=" + UTF8.String(key));
} }
} else { } else {
while(!found){ while(!found){
@@ -452,10 +456,12 @@ public final class TemplateEngine {
} }
} catch (final IOException e) { } catch (final IOException e) {
//file not found? //file not found?
ConcurrentLog.severe("FILEHANDLER","Include Error with file " + UTF8.String(filename) + ": " + e.getMessage()); ConcurrentLog.severe("FILEHANDLER","event=template.include subsystem=http result=failure servlet=" + servletname +
" file=" + UTF8.String(filename) + " reason=" + e.getMessage());
} finally { } finally {
if (br != null) try { br.close(); br=null; } catch (final Exception e) { if (br != null) try { br.close(); br=null; } catch (final Exception e) {
ConcurrentLog.warn("FILEHANDLER","Could not close buffered reader on file " + UTF8.String(filename)); ConcurrentLog.warn("FILEHANDLER","event=template.include subsystem=http result=close-failure servlet=" + servletname +
" file=" + UTF8.String(filename) + " reason=" + e.getMessage());
} }
} }
final PushbackInputStream pis2 = new PushbackInputStream(new ByteArrayInputStream(include.getBytes())); final PushbackInputStream pis2 = new PushbackInputStream(new ByteArrayInputStream(include.getBytes()));