Trace fill request

4 files changed, 190 insertions, 89 deletions

diff --git a/container-search/src/main/java/com/yahoo/search/Searcher.java b/container-search/src/main/java/com/yahoo/search/Searcher.java
index 3c4d3332144..69025271430 100644
--- a/container-search/src/main/java/com/yahoo/search/Searcher.java
+++ b/container-search/src/main/java/com/yahoo/search/Searcher.java
@@ -161,6 +161,13 @@ public abstract class Searcher extends Processor {
         if ( ! result.isFilled(summaryClass)) {
             fill(result, summaryClass, execution);
         }
+        else {
+            int fillRejectTraceAt = 3;
+            if (result.getQuery().getTraceLevel() >= fillRejectTraceAt)
+                result.getQuery().trace("Ignoring fill(" + summaryClass + "): " +
+                                        ( result.hits().getFilled() == null ? "Hits are unfillable" : "Hits already filled" ) +
+                                        ": result.hits().getFilled()=" + result.hits().getFilled(), fillRejectTraceAt);
+        }
     }
 
     /** Returns a logger unique for the instance subclass */
diff --git a/container-search/src/main/java/com/yahoo/search/searchchain/Execution.java b/container-search/src/main/java/com/yahoo/search/searchchain/Execution.java
index b53ade45d07..cde03c9069d 100644
--- a/container-search/src/main/java/com/yahoo/search/searchchain/Execution.java
+++ b/container-search/src/main/java/com/yahoo/search/searchchain/Execution.java
@@ -516,9 +516,7 @@ public class Execution extends com.yahoo.processing.execution.Execution {
         final int traceDependencies = 6;
         Query query = (Query) request;
         if (query.getTraceLevel() >= traceDependencies) {
-            query.trace(new StringBuilder().append(processor.getId())
-                    .append(" ").append(processor.getDependencies().toString())
-                    .toString(), traceDependencies);
+            query.trace(processor.getId() + " " + processor.getDependencies(), traceDependencies);
         }
     }
 
@@ -582,27 +580,15 @@ public class Execution extends com.yahoo.processing.execution.Execution {
     }
 
     private void onInvokingFill(Searcher searcher, Result result, String summaryClass) {
-        /* TODO
-        final int traceDependencies = 6;
-        Query query = (Query) request;
-        if (query.getTraceLevel() >= traceDependencies) {
-            query.trace(new StringBuilder().append(processor.getId())
-                                .append(" ").append(processor.getDependencies().toString())
-                                .toString(), traceDependencies);
-        }
-        */
+        int traceFillAt = 5;
+        if (trace().getTraceLevel() < traceFillAt) return;
+        trace().trace("Invoke fill(" + summaryClass + ") on " + searcher, traceFillAt);
     }
 
     private void onReturningFill(Searcher searcher, Result result, String summaryClass) {
-        /* TODO
-        final int traceDependencies = 6;
-        Query query = (Query) request;
-        if (query.getTraceLevel() >= traceDependencies) {
-            query.trace(new StringBuilder().append(processor.getId())
-                                .append(" ").append(processor.getDependencies().toString())
-                                .toString(), traceDependencies);
-        }
-        */
+        int traceFillAt = 5;
+        if (trace().getTraceLevel() < traceFillAt) return;
+        trace().trace("Return fill(" + summaryClass + ") on " + searcher, traceFillAt);
     }
 
     /** Calls ping on the next search in this chain. If there is no next, a Pong is created and returned. */
diff --git a/container-search/src/test/java/com/yahoo/search/searchchain/test/SearchChainTestCase.java b/container-search/src/test/java/com/yahoo/search/searchchain/test/SearchChainTestCase.java
index ad0c4796549..0d87d4448f4 100644
--- a/container-search/src/test/java/com/yahoo/search/searchchain/test/SearchChainTestCase.java
+++ b/container-search/src/test/java/com/yahoo/search/searchchain/test/SearchChainTestCase.java
@@ -2,6 +2,7 @@
 package com.yahoo.search.searchchain.test;
 
 import static com.yahoo.search.searchchain.test.SimpleSearchChain.searchChain;
+import static org.junit.Assert.assertEquals;
 
 import java.util.ArrayList;
 import java.util.Arrays;
@@ -18,6 +19,7 @@ import com.yahoo.search.Result;
 import com.yahoo.search.Searcher;
 import com.yahoo.search.searchchain.Execution;
 import com.yahoo.search.searchchain.SearchChain;
+import org.junit.Test;
 
 /**
  * Tests basic search chain functionality - creation, inheritance and ordering
@@ -25,17 +27,15 @@ import com.yahoo.search.searchchain.SearchChain;
  * @author bratseth
  */
 @SuppressWarnings("deprecation")
-public class SearchChainTestCase extends junit.framework.TestCase {
-
-    public SearchChainTestCase(String name) {
-        super(name);
-    }
+public class SearchChainTestCase {
 
+    @Test
     public void testEmptySearchChain() {
         SearchChain empty = new SearchChain(new ComponentId("empty"));
         assertEquals("empty", empty.getId().getName());
     }
 
+    @Test
     public void testSearchChainCreation() {
         assertEquals("test",searchChain.getId().stringValue());
         assertEquals("test",searchChain.getId().getName());
@@ -59,22 +59,27 @@ public class SearchChainTestCase extends junit.framework.TestCase {
         assertEquals(new HashSet<>(correct),new HashSet<>(test));
     }
 
+    @Test
     public void testSearchChainToStringEmpty() {
         assertEquals("chain 'test' []", new Chain<>(new ComponentId("test"), createSearchers(0)).toString());
     }
 
+    @Test
     public void testSearchChainToStringVeryShort() {
         assertEquals("chain 'test' [s1]", new Chain<>(new ComponentId("test"),createSearchers(1)).toString());
     }
 
+    @Test
     public void testSearchChainToStringShort() {
         assertEquals("chain 'test' [s1 -> s2 -> s3]", new Chain<>(new ComponentId("test"),createSearchers(3)).toString());
     }
 
+    @Test
     public void testSearchChainToStringLong() {
         assertEquals("chain 'test' [s1 -> s2 -> ... -> s4]", new Chain<>(new ComponentId("test"),createSearchers(4)).toString());
     }
 
+    @Test
     public void testSearchChainToStringVeryLong() {
         assertEquals("chain 'test' [s1 -> s2 -> ... -> s10]", new Chain<>(new ComponentId("test"),createSearchers(10)).toString());
     }
diff --git a/container-search/src/test/java/com/yahoo/search/searchchain/test/TraceTestCase.java b/container-search/src/test/java/com/yahoo/search/searchchain/test/TraceTestCase.java
index a0641374a62..0833fef47bf 100644
--- a/container-search/src/test/java/com/yahoo/search/searchchain/test/TraceTestCase.java
+++ b/container-search/src/test/java/com/yahoo/search/searchchain/test/TraceTestCase.java
@@ -1,13 +1,16 @@
 // Copyright 2016 Yahoo Inc. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
 package com.yahoo.search.searchchain.test;
 
+import com.yahoo.component.ComponentId;
 import com.yahoo.component.chain.Chain;
 import com.yahoo.search.Query;
 import com.yahoo.search.Result;
 import com.yahoo.search.Searcher;
+import com.yahoo.search.result.Hit;
 import com.yahoo.search.searchchain.Execution;
 import com.yahoo.yolean.trace.TraceNode;
 import com.yahoo.yolean.trace.TraceVisitor;
+import org.junit.Test;
 
 import java.io.IOException;
 import java.io.StringWriter;
@@ -16,38 +19,112 @@ import java.util.Arrays;
 import java.util.Iterator;
 import java.util.List;
 
+import static org.junit.Assert.assertEquals;
+import static org.junit.Assert.assertFalse;
+
 /**
  * Tests tracing scenarios where traces from multiple executions over the same query are involved.
  *
  * @author bratseth
  */
-public class TraceTestCase extends junit.framework.TestCase {
+public class TraceTestCase {
 
+    @Test
     public void testTracingOnCorrectAPIUseNonParallel() {
         assertTracing(true,false);
     }
 
+    @Test
     public void testTracingOnIncorrectAPIUseNonParallel() {
         assertTracing(false,false);
     }
 
+    @Test
     public void testTracingOnCorrectAPIUseParallel() {
         assertTracing(true, true);
     }
 
+    @Test
     public void testTracingOnIncorrectAPIUseParallel() {
         assertTracing(false,true);
     }
+    
+    @Test 
+    public void testTraceInvocationsUnfillableHits() {
+        final int traceLevel = 5;
+        Query query = new Query("?tracelevel=" + traceLevel);
+        Chain<Searcher> forkingChain = new Chain<>(new Tracer("tracer1"), 
+                                                   new Tracer("tracer2"), 
+                                                   new Backend("backend1", false));
+        Execution execution = new Execution(forkingChain, Execution.Context.createContextStub());
+        Result result = execution.search(query);
+        execution.fill(result, "mySummary");
+
+        Iterator<String> trace = collectTrace(query).iterator();
+        assertEquals("(level start)", trace.next());
+        assertEquals("  No query profile is used", trace.next());
+        trace.next(); // (properties trace: not checked)
+        assertEquals("  (level start)", trace.next());
+        assertEquals("    Invoke searcher 'tracer1'", trace.next());
+        assertEquals("    During tracer1: 0", trace.next());
+        assertEquals("    Invoke searcher 'tracer2'", trace.next());
+        assertEquals("    During tracer2: 0", trace.next());
+        assertEquals("    Invoke searcher 'backend1'", trace.next());
+        assertEquals("    Return searcher 'backend1'", trace.next());
+        assertEquals("    Return searcher 'tracer2'", trace.next());
+        assertEquals("    Return searcher 'tracer1'", trace.next());
+        assertEquals("    Invoke fill(mySummary) on searcher 'tracer1'", trace.next());
+        assertEquals("    Ignoring fill(mySummary): Hits are unfillable: result.hits().getFilled()=null", trace.next());
+        assertEquals("    Return fill(mySummary) on searcher 'tracer1'", trace.next());
+        assertEquals("  (level end)", trace.next());
+        assertEquals("(level end)", trace.next());
+        assertFalse(trace.hasNext());
+    }
 
-    @SuppressWarnings("deprecation")
-    public void assertTracing(boolean carryOverContext,boolean parallel) {
-        Query query=new Query("?tracelevel=1");
+    @Test
+    public void testTraceInvocationsFillableHits() {
+        final int traceLevel = 5;
+        Query query = new Query("?tracelevel=" + traceLevel);
+        Chain<Searcher> forkingChain = new Chain<>(new Tracer("tracer1"),
+                                                   new Tracer("tracer2"),
+                                                   new Backend("backend1", true));
+        Execution execution = new Execution(forkingChain, Execution.Context.createContextStub());
+        Result result = execution.search(query);
+        execution.fill(result, "mySummary");
+
+        Iterator<String> trace = collectTrace(query).iterator();
+        assertEquals("(level start)", trace.next());
+        assertEquals("  No query profile is used", trace.next());
+        trace.next(); // (properties trace: not checked)
+        assertEquals("  (level start)", trace.next());
+        assertEquals("    Invoke searcher 'tracer1'", trace.next());
+        assertEquals("    During tracer1: 0", trace.next());
+        assertEquals("    Invoke searcher 'tracer2'", trace.next());
+        assertEquals("    During tracer2: 0", trace.next());
+        assertEquals("    Invoke searcher 'backend1'", trace.next());
+        assertEquals("    Return searcher 'backend1'", trace.next());
+        assertEquals("    Return searcher 'tracer2'", trace.next());
+        assertEquals("    Return searcher 'tracer1'", trace.next());
+        assertEquals("    Invoke fill(mySummary) on searcher 'tracer1'", trace.next());
+        assertEquals("    Invoke fill(mySummary) on searcher 'tracer2'", trace.next());
+        assertEquals("    Invoke fill(mySummary) on searcher 'backend1'", trace.next());
+        assertEquals("    Return fill(mySummary) on searcher 'backend1'", trace.next());
+        assertEquals("    Return fill(mySummary) on searcher 'tracer2'", trace.next());
+        assertEquals("    Return fill(mySummary) on searcher 'tracer1'", trace.next());
+        assertEquals("  (level end)", trace.next());
+        assertEquals("(level end)", trace.next());
+        assertFalse(trace.hasNext());
+    }
+
+    private void assertTracing(boolean carryOverContext, boolean parallel) {
+        Query query = new Query("?tracelevel=1");
         query.trace("Before execution",1);
-        Chain<Searcher> forkingChain=new Chain<>(new Tracer("forker"),new Forker(carryOverContext,parallel,new Tracer("branch 1"),new Tracer("branch 2")));
+        Chain<Searcher> forkingChain = new Chain<>(new Tracer("forker"), 
+                                                   new Forker(carryOverContext, parallel, 
+                                                              new Tracer("branch 1") ,
+                                                              new Tracer("branch 2")));
         new Execution(forkingChain, Execution.Context.createContextStub()).search(query);
 
-        // printTrace(query);
-
         if (carryOverContext)
             assertTraceWithChildExecutionMessages(query);
         else if (parallel)
@@ -60,20 +137,20 @@ public class TraceTestCase extends junit.framework.TestCase {
 
     // The valid and usual trace
     private void assertTraceWithChildExecutionMessages(Query query) {
-        Iterator<String> trace=collectTrace(query).iterator();
-        assertEquals("(level start)",trace.next());
-        assertEquals("  No query profile is used",trace.next());
-        assertEquals("  Before execution",trace.next());
-        assertEquals("  (level start)",trace.next());
-        assertEquals("    During forker: 0",trace.next());
-        assertEquals("    (level start)",trace.next());
-        assertEquals("      During branch 1: 0",trace.next());
-        assertEquals("    (level end)",trace.next());
-        assertEquals("    (level start)",trace.next());
+        Iterator<String> trace = collectTrace(query).iterator();
+        assertEquals("(level start)", trace.next());
+        assertEquals("  No query profile is used", trace.next());
+        assertEquals("  Before execution", trace.next());
+        assertEquals("  (level start)", trace.next());
+        assertEquals("    During forker: 0", trace.next());
+        assertEquals("    (level start)", trace.next());
+        assertEquals("      During branch 1: 0", trace.next());
+        assertEquals("    (level end)", trace.next());
+        assertEquals("    (level start)", trace.next());
         assertEquals("      During branch 2: 0", trace.next());
-        assertEquals("    (level end)",trace.next());
-        assertEquals("  (level end)",trace.next());
-        assertEquals("(level end)",trace.next());
+        assertEquals("    (level end)", trace.next());
+        assertEquals("  (level end)", trace.next());
+        assertEquals("(level end)", trace.next());
         assertFalse(trace.hasNext());
     }
 
@@ -81,19 +158,19 @@ public class TraceTestCase extends junit.framework.TestCase {
     // where the message of the execution subtrees is empty rather than "child execution". This is fine.
     private void assertTrace(Query query) {
         Iterator<String> trace=collectTrace(query).iterator();
-        assertEquals("(level start)",trace.next());
-        assertEquals("  No query profile is used",trace.next());
-        assertEquals("  Before execution",trace.next());
-        assertEquals("  (level start)",trace.next());
-        assertEquals("    During forker: 0",trace.next());
-        assertEquals("    (level start)",trace.next());
-        assertEquals("      During branch 1: 0",trace.next());
-        assertEquals("    (level end)",trace.next());
-        assertEquals("    (level start)",trace.next());
+        assertEquals("(level start)", trace.next());
+        assertEquals("  No query profile is used", trace.next());
+        assertEquals("  Before execution", trace.next());
+        assertEquals("  (level start)", trace.next());
+        assertEquals("    During forker: 0", trace.next());
+        assertEquals("    (level start)", trace.next());
+        assertEquals("      During branch 1: 0", trace.next());
+        assertEquals("    (level end)", trace.next());
+        assertEquals("    (level start)", trace.next());
         assertEquals("      During branch 2: 0", trace.next());
-        assertEquals("    (level end)",trace.next());
-        assertEquals("  (level end)",trace.next());
-        assertEquals("(level end)",trace.next());
+        assertEquals("    (level end)", trace.next());
+        assertEquals("  (level end)", trace.next());
+        assertEquals("(level end)", trace.next());
         assertFalse(trace.hasNext());
     }
 
@@ -101,27 +178,27 @@ public class TraceTestCase extends junit.framework.TestCase {
     // but all the trace messages are present.
     private void assertIncorrectlyNestedTrace(Query query) {
         Iterator<String> trace=collectTrace(query).iterator();
-        assertEquals("(level start)",trace.next());
-        assertEquals("  No query profile is used",trace.next());
-        assertEquals("  Before execution",trace.next());
-        assertEquals("  (level start)",trace.next());
-        assertEquals("    During forker: 0",trace.next());
-        assertEquals("    (level start)",trace.next());
-        assertEquals("      During branch 1: 0",trace.next());
-        assertEquals("      (level start)",trace.next());
+        assertEquals("(level start)", trace.next());
+        assertEquals("  No query profile is used", trace.next());
+        assertEquals("  Before execution", trace.next());
+        assertEquals("  (level start)", trace.next());
+        assertEquals("    During forker: 0", trace.next());
+        assertEquals("    (level start)", trace.next());
+        assertEquals("      During branch 1: 0", trace.next());
+        assertEquals("      (level start)", trace.next());
         assertEquals("        During branch 2: 0", trace.next());
-        assertEquals("      (level end)",trace.next());
-        assertEquals("    (level end)",trace.next());
-        assertEquals("  (level end)",trace.next());
-        assertEquals("(level end)",trace.next());
+        assertEquals("      (level end)", trace.next());
+        assertEquals("    (level end)", trace.next());
+        assertEquals("  (level end)", trace.next());
+        assertEquals("(level end)", trace.next());
         assertFalse(trace.hasNext());
     }
 
     private void assertCorrectRendering(Query query) {
         try {
-            StringWriter writer=new StringWriter();
+            StringWriter writer = new StringWriter();
             query.getContext(false).render(writer);
-            String expected=
+            String expected =
                     "<meta type=\"context\">\n" +
                     "\n" +
                     "  <p>No query profile is used</p>\n" +
@@ -130,7 +207,7 @@ public class TraceTestCase extends junit.framework.TestCase {
                     "\n" +
                     "  <p>\n" +
                     "    <p>During forker: 0";
-            assertEquals(expected,writer.toString().substring(0,expected.length()));
+            assertEquals(expected, writer.toString().substring(0, expected.length()));
         }
         catch (IOException e) {
             throw new RuntimeException(e);
@@ -138,15 +215,15 @@ public class TraceTestCase extends junit.framework.TestCase {
     }
 
     private List<String> collectTrace(Query query) {
-        TraceCollector collector=new TraceCollector();
+        TraceCollector collector = new TraceCollector();
         query.getContext(false).getTrace().accept(collector);
         return collector.trace();
     }
 
     private static class TraceCollector extends TraceVisitor {
 
-        private List<String> trace=new ArrayList<>();
-        private StringBuilder indent=new StringBuilder();
+        private List<String> trace = new ArrayList<>();
+        private StringBuilder indent = new StringBuilder();
 
         @Override
         public void entering(TraceNode node) {
@@ -156,14 +233,14 @@ public class TraceTestCase extends junit.framework.TestCase {
 
         @Override
         public void leaving(TraceNode end) {
-            indent.setLength(indent.length()-2);
+            indent.setLength(indent.length() - 2);
             trace.add(indent + "(level end)");
         }
 
         @Override
         public void visit(TraceNode node) {
             if (node.isRoot()) return;
-            if (node.payload()==null) return;
+            if (node.payload() == null) return;
             trace.add(indent + node.payload().toString());
         }
 
@@ -173,15 +250,16 @@ public class TraceTestCase extends junit.framework.TestCase {
     private static class Tracer extends Searcher {
 
         private String name;
-        private int counter=0;
+        private int counter = 0;
 
         public Tracer(String name) {
-            this.name=name;
+            super(new ComponentId(name));
+            this.name = name;
         }
 
         @Override
         public Result search(Query query, Execution execution) {
-            query.trace("During " + name + ": " + (counter++) ,1);
+            query.trace("During " + name + ": " + (counter++),1);
             return execution.search(query);
         }
     }
@@ -196,20 +274,21 @@ public class TraceTestCase extends junit.framework.TestCase {
         /** If true, simulate parallel execution by cloning the query */
         private boolean parallel;
 
-        public Forker(boolean carryOverContext,boolean parallel,Searcher ... branches) {
-            this.carryOverContext=carryOverContext;
-            this.parallel=parallel;
-            this.branches=Arrays.asList(branches);
+        public Forker(boolean carryOverContext, boolean parallel, Searcher ... branches) {
+            this.carryOverContext = carryOverContext;
+            this.parallel = parallel;
+            this.branches = Arrays.asList(branches);
         }
 
         @SuppressWarnings("deprecation")
         @Override
         public Result search(Query query, Execution execution) {
-            Result result=execution.search(query);
+            Result result = execution.search(query);
             for (Searcher branch : branches) {
-                Query branchQuery=parallel ? query.clone() : query;
-                Result branchResult=
-                        ( carryOverContext ? new Execution(branch,execution.context()) : new Execution(branch, Execution.Context.createContextStub())).search(branchQuery);
+                Query branchQuery = parallel ? query.clone() : query;
+                Result branchResult =
+                        ( carryOverContext ? new Execution(branch, execution.context()) : 
+                                             new Execution(branch, Execution.Context.createContextStub())).search(branchQuery);
                 result.hits().add(branchResult.hits());
                 result.mergeWith(branchResult);
             }
@@ -218,4 +297,28 @@ public class TraceTestCase extends junit.framework.TestCase {
 
     }
 
+    private static class Backend extends Searcher {
+
+        private final boolean fillableHits;
+        
+        public Backend(String name, boolean fillableHits) {
+            super(new ComponentId(name));
+            this.fillableHits = fillableHits;
+        }
+
+        @Override
+        public Result search(Query query, Execution execution) {
+            Result result = execution.search(query);
+            Hit hit0 = new Hit("hit:0");
+            Hit hit1 = new Hit("hit:1");
+            if (fillableHits) {
+                hit0.setFillable();
+                hit1.setFillable();
+            }
+            result.hits().add(hit0);
+            result.hits().add(hit1);
+            return result;
+        }
+    }
+
 }