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

12 files changed, 290 insertions, 135 deletions

diff --git a/source/net/yacy/document/TextParser.java b/source/net/yacy/document/TextParser.java
index 70ccf63c1..79dace94e 100644
--- a/source/net/yacy/document/TextParser.java
+++ b/source/net/yacy/document/TextParser.java
@@ -83,6 +83,13 @@ public final class TextParser {
 
     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 */
     private static final Parser genericXMLIdiom = new GenericXMLParser();
 
@@ -262,7 +269,7 @@ public final class TextParser {
             final Date lastModified
             ) throws Parser.Failure {
         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);
         final Set<Parser> idioms = new HashSet<>();
@@ -286,14 +293,14 @@ public final class TextParser {
             final long maxBytes,
             final Date lastModified
             ) 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);
         Set<Parser> idioms = null;
         try {
             idioms = parsers(location, mimeType);
         } catch (final Parser.Failure e) {
             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);
         }
         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 */
                 for(final Parser parser : idioms) {
+                    final long parserStart = System.currentTimeMillis();
                     /* 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 */
                     CloseShieldInputStream nonCloseInputStream = CloseShieldInputStream.wrap(markableStream);
@@ -342,6 +350,9 @@ public final class TextParser {
                         return parseSource(location, mimeType, parser, charset, defaultValency, valencySwitchTagNames, scraper, timezoneOffset,
                                 nonCloseInputStream, maxLinks, maxBytes, lastModified);
                     } 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 :
                          * too bad, the marks is invalid and process fails now with an IOException */
                         markableStream.reset();
@@ -362,12 +373,15 @@ public final class TextParser {
                             final Document maindoc = gzipParser.createMainDocument(location, mimeType, charset, gzParser);
 
                             try {
+                                final long gzipFallbackStart = System.currentTimeMillis();
                                 final Document[] docs = gzParser.parseCompressedInputStream(location,
                                         charset, timezoneOffset, depth,
                                         nonCloseInputStream, maxLinks, maxBytes);
                                 if (docs != null) {
                                     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 };
                             } catch(final Exception e1) {
                                 /* 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
             ) throws Parser.Failure {
         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);
         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
         for (final Parser parser: parsers) {
             if (MemoryControl.request(sourceArray.length * 6, false)) {
+                final long parserStart = System.currentTimeMillis();
                 ByteArrayInputStream bis;
                 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.
@@ -594,6 +609,9 @@ public final class TextParser {
                         docs = parser.parse(location, mimeType, documentCharset, defaultValency, valencySwitchTagNames, scraper, timezoneOffset, bis);
                     }
                 } 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 &&
                             (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,
@@ -610,6 +628,7 @@ public final class TextParser {
                         final Document maindoc = gzipParser.createMainDocument(location, mimeType, charset, gzParser);
 
                         try {
+                            final long gzipFallbackStart = System.currentTimeMillis();
                             docs = gzParser.parseCompressedInputStream(location,
                                     charset, timezoneOffset, depth,
                                     bis, maxLinks, maxBytes);
@@ -617,6 +636,8 @@ public final class TextParser {
                                 maindoc.addSubDocuments(docs);
                             }
                             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;
                         } catch(final Parser.Failure e1) {
                             failedParser.put(parser, e1);
@@ -627,6 +648,9 @@ public final class TextParser {
                         failedParser.put(parser, 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));
                     //log.logWarning("tried parser '" + parser.getName() + "' to parse " + location.toNormalform(true, false) + " but failed: " + e.getMessage(), e);
                 } finally {
@@ -649,7 +673,8 @@ public final class TextParser {
             }
             String failedParsers = "";
             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() + " ";
             }
             throw new Parser.Failure("All parser failed: " + failedParsers, location);
diff --git a/source/net/yacy/htroot/yacy/hello.java b/source/net/yacy/htroot/yacy/hello.java
index 26d106682..acb073225 100644
--- a/source/net/yacy/htroot/yacy/hello.java
+++ b/source/net/yacy/htroot/yacy/hello.java
@@ -115,9 +115,20 @@ public final class hello {
         // we easily know the caller's IP:

         final String userAgent = header.get(HeaderFramework.USER_AGENT, "<unknown>");

         sb.peers.peerActions.setUserAgent(clientip, userAgent);

-        final Set<String> reportedips = remoteSeed.getIPs();

-        final String reportedPeerType = remoteSeed.get(Seed.PEERTYPE, Seed.PEERTYPE_JUNIOR);

-        //final double clientversion = remoteSeed.getVersion();

+        final Set<String> reportedips = remoteSeed.getIPs();
+        final String reportedPeerType = remoteSeed.get(Seed.PEERTYPE, Seed.PEERTYPE_JUNIOR);
+        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 (sb.peers.mySeed().clash(reportedips)) {

@@ -167,11 +178,14 @@ public final class hello {
             for (final String reportedip: reportedips) {

                 final int partialtimeout = ((int) (callbackStart + totalTimeout - System.currentTimeMillis())) / callbackRemain; // bad hack until a concurrent version is implemented

                 if (partialtimeout <= 0) break;

-                //ConcurrentLog.info("**hello-DEBUG**", "reportedip = " + reportedip + " is handled");

-                if (Seed.isProperIP(reportedip)) {

-                    //ConcurrentLog.info("**hello-DEBUG**", "starting callback to reportedip = " + reportedip + ", timeout = " + partialtimeout);

-                    prop.put("yourip", reportedip);

-                    remoteSeed.setIP(reportedip);

+                //ConcurrentLog.info("**hello-DEBUG**", "reportedip = " + reportedip + " is handled");
+                if (Seed.isProperIP(reportedip)) {
+                    if (Network.log.isFine()) Network.log.fine("hello/server: backping candidate peer='" + remoteSeed.getName()
+                            + "', address=" + reportedip + ", addressFamily=" + Seed.addressFamily(reportedip)
+                            + ", remainingCandidates=" + callbackRemain);
+                    //ConcurrentLog.info("**hello-DEBUG**", "starting callback to reportedip = " + reportedip + ", timeout = " + partialtimeout);
+                    prop.put("yourip", reportedip);
+                    remoteSeed.setIP(reportedip);
                     time = System.currentTimeMillis();

                     try {

                     	MultiProtocolURL remoteBaseURL = remoteSeed.getPublicMultiprotocolURL(reportedip, preferHttps);

diff --git a/source/net/yacy/http/CrashProtectionHandler.java b/source/net/yacy/http/CrashProtectionHandler.java
index 0ca88497e..12ae12c5c 100644
--- a/source/net/yacy/http/CrashProtectionHandler.java
+++ b/source/net/yacy/http/CrashProtectionHandler.java
@@ -13,6 +13,8 @@ import org.eclipse.jetty.server.Request;
 import org.eclipse.jetty.server.Server;
 import org.eclipse.jetty.server.handler.HandlerWrapper;
 
+import net.yacy.cora.util.ConcurrentLog;
+
 public class CrashProtectionHandler extends HandlerWrapper implements Handler, HandlerContainer {
 	
 	public CrashProtectionHandler() {
@@ -32,6 +34,8 @@ public class CrashProtectionHandler extends HandlerWrapper implements Handler, H
 		try {
 			super.handle(target, baseRequest, request, response);
 		} 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
 			writeResponse(request, response, e);
                         baseRequest.setHandled(true);
diff --git a/source/net/yacy/http/servlets/YaCyDefaultServlet.java b/source/net/yacy/http/servlets/YaCyDefaultServlet.java
index 46f1675ab..c52cb828c 100644
--- a/source/net/yacy/http/servlets/YaCyDefaultServlet.java
+++ b/source/net/yacy/http/servlets/YaCyDefaultServlet.java
@@ -169,11 +169,11 @@ public class YaCyDefaultServlet extends HttpServlet  {
             } else {

                 this._resourceBase = Resource.newResource(sb.getConfig(SwitchboardConstants.HTROOT_PATH, SwitchboardConstants.HTROOT_PATH_DEFAULT)); //default

             }

-        } catch (final IOException e) {

-            ConcurrentLog.severe("FILEHANDLER", "YaCyDefaultServlet: resource base (htRootPath) missing");

-            ConcurrentLog.logException(e);

-            throw new UnavailableException(e.toString());

-        }

+        } catch (final IOException e) {
+            ConcurrentLog.severe("FILEHANDLER", "event=http.resource subsystem=http result=missing-resource-base reason=" + e.getMessage());
+            ConcurrentLog.logException(e);
+            throw new UnavailableException(e.toString());
+        }
         if (ConcurrentLog.isFine("FILEHANDLER")) {

             ConcurrentLog.fine("FILEHANDLER","YaCyDefaultServlet: resource base = " + this._resourceBase);

         }

@@ -351,11 +351,12 @@ public class YaCyDefaultServlet extends HttpServlet  {
                     }

                 }

             }

-        } catch (final IllegalArgumentException e) {

-            ConcurrentLog.logException(e);

-            if (!response.isCommitted()) {

-                response.sendError(HttpServletResponse.SC_INTERNAL_SERVER_ERROR, e.getMessage());

-            }

+        } catch (final IllegalArgumentException e) {
+            ConcurrentLog.warn("FILEHANDLER", "event=http.resource subsystem=http result=illegal-argument path=" + pathInContext +
+                    " reason=" + e.getMessage());
+            if (!response.isCommitted()) {
+                response.sendError(HttpServletResponse.SC_INTERNAL_SERVER_ERROR, e.getMessage());
+            }
         } finally {

             if (resource != null) {

                 resource.close();

@@ -406,7 +407,9 @@ public class YaCyDefaultServlet extends HttpServlet  {
             }
             return buffer.toString(StandardCharsets.UTF_8.name());
         } 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;
         }
     }

diff --git a/source/net/yacy/peers/Network.java b/source/net/yacy/peers/Network.java
index d29fed7c9..9071ba5e0 100644
--- a/source/net/yacy/peers/Network.java
+++ b/source/net/yacy/peers/Network.java
@@ -205,10 +205,13 @@ public class Network
 						SwitchboardConstants.NETWORK_PROTOCOL_HTTPS_PREFERRED,
 						SwitchboardConstants.NETWORK_PROTOCOL_HTTPS_PREFERRED_DEFAULT);
                 for (final String ip: this.seed.getIPs()) {
-                	try {
-                		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()) {
+	                	try {
+                            if (log.isFine()) log.fine("publish: attempting " + this.seed.get(Seed.PEERTYPE, Seed.PEERTYPE_SENIOR) + " peer '"
+                                    + this.seed.getName() + "' address=" + ip + ", addressFamily=" + Seed.addressFamily(ip)
+                                    + ", 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 */
 							targetBaseURL = this.seed.getPublicMultiprotocolURL(ip, false);
 							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);
 							}
 						}
-                        if(result == null) {
-                            // no or wrong response, delete that address
-                            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);
-                            Network.this.sb.peers.peerActions.interfaceDeparture(this.seed, ip);
-                            continue;
-                        }
-                	} catch(final MalformedURLException e) {
-                        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);
-                        Network.this.sb.peers.peerActions.interfaceDeparture(this.seed, ip);
-                		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() + "' at " + this.seed.getIPs());
+	                        if(result == null) {
+	                            // no or wrong response, delete that address
+	                            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()
+                                    + "' address=" + ip + ", addressFamily=" + Seed.addressFamily(ip)
+                                    + ", seedAddressProfile=" + Seed.addressProfile(this.seed.getIPs()) + ": " + cause);
+	                            Network.this.sb.peers.peerActions.interfaceDeparture(this.seed, ip);
+	                            continue;
+	                        }
+	                	} catch(final MalformedURLException e) {
+	                        final String cause = "malformed peer URL";
+	                        log.info("publish: disconnected " + this.seed.get(Seed.PEERTYPE, Seed.PEERTYPE_SENIOR) + " peer '" + this.seed.getName()
+                                + "' address=" + ip + ", addressFamily=" + Seed.addressFamily(ip)
+                                + ", seedAddressProfile=" + Seed.addressProfile(this.seed.getIPs()) + ": " + cause);
+	                        Network.this.sb.peers.peerActions.interfaceDeparture(this.seed, ip);
+	                		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
                     final Seed newSeed = Network.this.sb.peers.getConnected(this.seed.hash);
                     if ( newSeed != null ) {
@@ -278,7 +287,8 @@ public class Network
             } catch (final Exception e ) {
                 ConcurrentLog.logException(e);
                 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);
             }
         }
@@ -375,17 +385,20 @@ public class Network
 
                 final Set<String> ips = seed.getIPs();
                 if(ips.isEmpty()) {
-                	/* This should not happen : seeds db maintains only seeds with at least one IP */
-                	log.warn("Peer " + seed.getName() + "has no known IP address");
+	                	/* This should not happen : seeds db maintains only seeds with at least one IP */
+	                	log.warn("publish: peer '" + seed.getName() + "' has no known IP address, seedAddressProfile=" + Seed.addressProfile(ips));
                 } else {
-                	final String ip = ips.iterator().next();
-                	final String address = seed.getPublicAddress(ip);
-                	if ( log.isFine() ) log.fine("HELLO #" + i + " to peer '" + seed.getName() + "' at " + address); // debug
-                	final String seederror = seed.isProper(false);
-                	if ( (address == null) || (seederror != null) ) {
-                		// we don't like that address, delete it
-                		this.sb.peers.peerActions.interfaceDeparture(seed, ip);
-                	} else {
+	                	final String ip = ips.iterator().next();
+	                	final String address = seed.getPublicAddress(ip);
+	                	if ( log.isFine() ) log.fine("HELLO #" + i + " to peer '" + seed.getName() + "' at " + address); // debug
+	                	final String seederror = seed.isProper(false);
+	                	if ( (address == null) || (seederror != null) ) {
+                            log.info("publish: skipping peer '" + seed.getName() + "' before publish thread, address="
+                                    + ip + ", addressFamily=" + Seed.addressFamily(ip) + ", publicAddress=" + address
+                                    + ", 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
                 		final publishThread t = new publishThread(Network.publishThreadGroup, seed);
                 		t.start();
diff --git a/source/net/yacy/peers/Protocol.java b/source/net/yacy/peers/Protocol.java
index f81caaa57..b874a7676 100644
--- a/source/net/yacy/peers/Protocol.java
+++ b/source/net/yacy/peers/Protocol.java
@@ -516,16 +516,23 @@ public final class Protocol {
         // partitions : number of remote peers that are asked (for evaluation of QPM)

         // duetime    : maximum time that a peer should spent to create a result

 

-        final long timestamp = System.currentTimeMillis();

-        event.addExpectedRemoteReferences(count);

-        SearchResult result = null;

-        for (String ip: target.getIPs()) {

-            //if (ip.indexOf(':') >= 0) System.out.println("Search target: IPv6: " + ip);

-            final String targetBaseURL;

-            if (target.clash(event.peers.mySeed().getIPs())) {

-                targetBaseURL = "http://localhost:" + event.peers.mySeed().getPort();

-            } else {

-                targetBaseURL = target.getPublicURL(ip,

+        final long timestamp = System.currentTimeMillis();
+        event.addExpectedRemoteReferences(count);
+        SearchResult result = null;
+        final boolean localClash = target.clash(event.peers.mySeed().getIPs());
+        if (localClash) {
+            Network.log.info("remote search: target peer '" + target.getName() + "'/" + target.hash
+                    + " clashes with local peer addresses; using localhost, targetAddressProfile="
+                    + Seed.addressProfile(target.getIPs()) + ", localAddressProfile="
+                    + Seed.addressProfile(event.peers.mySeed().getIPs()));
+        }
+        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,

                                 SwitchboardConstants.REMOTESEARCH_HTTPS_PREFERRED_DEFAULT));

             }

diff --git a/source/net/yacy/peers/Seed.java b/source/net/yacy/peers/Seed.java
index 189315665..b2fbc8edb 100644
--- a/source/net/yacy/peers/Seed.java
+++ b/source/net/yacy/peers/Seed.java
@@ -448,6 +448,35 @@ public class Seed implements Cloneable, Comparable<Seed>, Comparator<Seed>
         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) {
         final String normalizedLeft = Domains.chopZoneID(left);
         final String normalizedRight = Domains.chopZoneID(right);
diff --git a/source/net/yacy/peers/Transmission.java b/source/net/yacy/peers/Transmission.java
index e9eb59ed8..b025aa613 100644
--- a/source/net/yacy/peers/Transmission.java
+++ b/source/net/yacy/peers/Transmission.java
@@ -244,7 +244,12 @@ public class Transmission {
             // get possibly newer target Info
             final Seed newTarget = Transmission.this.seeds.get(this.dhtTarget.hash);
             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);
                     Transmission.this.seeds.updateConnected(newTarget);
                 } else {
diff --git a/source/net/yacy/repository/LoaderDispatcher.java b/source/net/yacy/repository/LoaderDispatcher.java
index f05d8bc8e..1fa31e5f3 100644
--- a/source/net/yacy/repository/LoaderDispatcher.java
+++ b/source/net/yacy/repository/LoaderDispatcher.java
@@ -99,9 +99,19 @@ public final class LoaderDispatcher {
     }

 

     @SuppressWarnings("unchecked")

-    public HashSet<String> getSupportedProtocols() {

-        return (HashSet<String>) this.supportedProtocols.clone();

-    }

+    public HashSet<String> getSupportedProtocols() {
+        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

@@ -169,12 +179,12 @@ public final class LoaderDispatcher {
         if (check != null && cacheStrategy != CacheStrategy.NOCACHE) {

             // a loading process is going on for that url

             //ConcurrentLog.info("LoaderDispatcher", "waiting for " + request.url().toNormalform(true));

-            final long t = System.currentTimeMillis();

-            try { check.tryAcquire(5, TimeUnit.SECONDS);} catch (final InterruptedException e) {}

-            ConcurrentLog.info("LoaderDispatcher", "waited " + (System.currentTimeMillis() - t) + " ms for " + request.url().toNormalform(true));

-            // now the process may have terminated and we run a normal loading

-            // which may be successful faster because of a cache hit

-        }

+            final long t = System.currentTimeMillis();
+            try { check.tryAcquire(5, TimeUnit.SECONDS);} catch (final InterruptedException e) {}
+            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
+            // which may be successful faster because of a cache hit
+        }
 

         this.loaderSteering.put(request.url(), new Semaphore(0));

         try {

@@ -208,11 +218,12 @@ public final class LoaderDispatcher {
         final String host = url.getHost();

         final CrawlProfile crawlProfile = request.profileHandle() == null ? null : this.sb.crawler.get(UTF8.getBytes(request.profileHandle()));

 

-        // check if url is in blacklist

-        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);

-            throw new IOException("DISPATCHER Rejecting URL '" + request.url().toString() + "'. 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())) {
+            LoaderDispatcher.log.warn("event=loader.reject subsystem=crawler reason=blacklist blacklistType=" + blacklistType + " " + requestLogMeta(request, url));
+            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

         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)

-        if (cacheStrategy == CacheStrategy.CACHEONLY) {

-            // we had a chance to get the content from the cache .. its over. We don't have it.

-            throw new IOException("cache only strategy");

-        }

+        if (cacheStrategy == CacheStrategy.CACHEONLY) {
+            // we had a chance to get the content from the cache .. its over. We don't have it.
+            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

 

@@ -250,12 +262,16 @@ public final class LoaderDispatcher {
         } else {

             throw new IOException("Unsupported protocol '" + protocol + "' in url " + url);

         }

-        if (response == null) {

-            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 == null) {
+            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) {
+            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

         // 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

                 if (cacheStrategy == CacheStrategy.IFEXIST || cacheStrategy == CacheStrategy.CACHEONLY) {

                     // well, just take the cache and don't care about freshness of the content

-                    final byte[] content = Cache.getContent(url.hash());

-                    if (content != null) {

-                        LoaderDispatcher.log.info("cache hit/useall for: " + url.toNormalform(true));

-                        response.setContent(content);

-                        return response;

-                    }

+                    final byte[] content = Cache.getContent(url.hash());
+                    if (content != null) {
+                        LoaderDispatcher.log.info("event=loader.cache subsystem=crawler result=hit mode=useall bytes=" + content.length + " " + requestLogMeta(request, url));
+                        response.setContent(content);
+                        return response;
+                    }
                 }

 

                 // now the cacheStrategy must be CACHE_STRATEGY_IFFRESH, that means we should do a proxy freshness test

                 //assert cacheStrategy == CacheStrategy.IFFRESH : "cacheStrategy = " + cacheStrategy;

                 if (response.isFreshForProxy()) {

-                    final byte[] content = Cache.getContent(url.hash());

-                    if (content != null) {

-                        LoaderDispatcher.log.info("cache hit/fresh for: " + url.toNormalform(true));

-                        response.setContent(content);

-                        return response;

-                    }

-                }

-                LoaderDispatcher.log.info("cache hit/stale for: " + url.toNormalform(true));

-                /* Cached content can not be used : we return a null response to ensure callers will detect no cache response is available */

-                response = null;

-            } else if (cachedResponse != null) {

-                LoaderDispatcher.log.warn("HTCACHE contained response header, but not content for url " + url.toNormalform(true));

-            }

-        }

-		return response;

+                    final byte[] content = Cache.getContent(url.hash());
+                    if (content != null) {
+                        LoaderDispatcher.log.info("event=loader.cache subsystem=crawler result=hit mode=fresh bytes=" + content.length + " " + requestLogMeta(request, url));
+                        response.setContent(content);
+                        return response;
+                    }
+                }
+                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 */
+                response = null;
+            } else if (cachedResponse != null) {
+                LoaderDispatcher.log.warn("event=loader.cache subsystem=crawler result=header-without-content " + requestLogMeta(request, url));
+            }
+        }
+		return response;
 	}

 

     /**

@@ -366,11 +382,12 @@ public final class LoaderDispatcher {
         final String host = url.getHost();

         final CrawlProfile crawlProfile = request.profileHandle() == null ? null : this.sb.crawler.get(UTF8.getBytes(request.profileHandle()));

 

-        // check if url is in blacklist

-        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);

-            throw new IOException("DISPATCHER Rejecting URL '" + request.url().toString() + "'. 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())) {
+            LoaderDispatcher.log.warn("event=loader.reject subsystem=crawler reason=blacklist blacklistType=" + blacklistType + " stream=true " + requestLogMeta(request, url));
+            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

         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)

-        if (cacheStrategy == CacheStrategy.CACHEONLY) {

-            // we had a chance to get the content from the cache .. its over. We don't have it.

-            throw new IOException("cache only strategy");

-        }

+        if (cacheStrategy == CacheStrategy.CACHEONLY) {
+            // we had a chance to get the content from the cache .. its over. We don't have it.
+            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

 

@@ -504,11 +522,11 @@ public final class LoaderDispatcher {
 				check.tryAcquire(5, TimeUnit.SECONDS);

 			} catch (final InterruptedException e) {

 			}

-			ConcurrentLog.info("LoaderDispatcher",

-					"waited " + (System.currentTimeMillis() - t) + " ms for " + request.url().toNormalform(true));

-			// now the process may have terminated and we run a normal loading

-			// which may be successful faster because of a cache hit

-		}

+			ConcurrentLog.info("LoaderDispatcher",
+					"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
+			// which may be successful faster because of a cache hit
+		}
 

 		this.loaderSteering.put(request.url(), new Semaphore(0));

 		try {

diff --git a/source/net/yacy/search/index/Fulltext.java b/source/net/yacy/search/index/Fulltext.java
index ce5dadacc..f841892fd 100644
--- a/source/net/yacy/search/index/Fulltext.java
+++ b/source/net/yacy/search/index/Fulltext.java
@@ -325,8 +325,11 @@ public final class Fulltext {
         final long t = System.currentTimeMillis();
         if (this.lastCommit + 10000 > t) return;
         this.lastCommit = t;
+        final long start = System.currentTimeMillis();
         this.getDefaultConnector().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;
         final String id = (String) doc.getFieldValue(CollectionSchema.id.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;
-        ConcurrentLog.info("Fulltext", "indexing: " + id + " " + url);
+        final long start = System.currentTimeMillis();
         try {
             connector.add(doc);
         } 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);
         }
+        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();
     }
 
     public void putEdges(final Collection<SolrInputDocument> edges) throws IOException {
         if (!this.useWebgraph()) return;
         if (edges == null || edges.size() == 0) return;
+        final long start = System.currentTimeMillis();
         try {
             this.getWebgraphConnector().add(edges);
         } 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);
         }
+        ConcurrentLog.info("Fulltext", "event=index.webgraph subsystem=index result=queued count=" + edges.size() +
+                " durationMs=" + (System.currentTimeMillis() - start));
         if (MemoryControl.shortStatus()) this.clearCaches();
     }
 
diff --git a/source/net/yacy/search/query/SearchEvent.java b/source/net/yacy/search/query/SearchEvent.java
index 7bc87f39d..8a053fdb5 100644
--- a/source/net/yacy/search/query/SearchEvent.java
+++ b/source/net/yacy/search/query/SearchEvent.java
@@ -700,6 +700,7 @@ public final class SearchEvent implements ScoreMapUpdatesListener {
             this.remote_rwi_stored.addAndGet(fullResource);
             this.remote_rwi_peerCount.incrementAndGet();
         }
+        final String queryString = this.query.getQueryGoal().getQueryString(false);
         long timer = System.currentTimeMillis();
 
         // normalize entries
@@ -729,12 +730,20 @@ public final class SearchEvent implements ScoreMapUpdatesListener {
             pollloop: while ( true ) {
                 remaining = timeout - System.currentTimeMillis();
                 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;
                 }
                 iEntry = decodedEntries.poll(remaining, TimeUnit.MILLISECONDS);
                 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;
                 }
                 if (iEntry == WordReferenceVars.poison) {
@@ -829,9 +838,16 @@ public final class SearchEvent implements ScoreMapUpdatesListener {
 
                 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 ) {
+            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);
diff --git a/source/net/yacy/server/http/TemplateEngine.java b/source/net/yacy/server/http/TemplateEngine.java
index 26224c049..9c9cef2d0 100644
--- a/source/net/yacy/server/http/TemplateEngine.java
+++ b/source/net/yacy/server/http/TemplateEngine.java
@@ -270,7 +270,8 @@ public final class TemplateEngine {
                             try{
                                 num=Integer.parseInt(pattern.get(patternKey)); // Key contains the iteration number as string
                             }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;
                             }
                         }
@@ -288,7 +289,8 @@ public final class TemplateEngine {
                         }//for
                         structure.append(open_endtag).append(multi_key).append(close_tagn);
                     } 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) {
                     transferUntil(pis, keyStream, appendBytes(PP, patternName, null, null));
                     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();
                         structure.close();
                         text.close();
@@ -343,7 +346,8 @@ public final class TemplateEngine {
                     structure.append(writeTemplate(servletname, pis2, out, pattern, newPrefix(prefix,key)));
                     transferUntil(pis, keyStream, appendBytes(hash_brackopen_slash, key, brackclose_hash, null));
                     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 {
                     while(!found){
@@ -452,10 +456,12 @@ public final class TemplateEngine {
                             }
                         } catch (final IOException e) {
                             //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 {
                             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()));