better rank feature back-traces

- log as additional lines on original failure message
- skip frames a bit after the middle, not at the very end

4 files changed, 58 insertions, 23 deletions

diff --git a/searchlib/src/tests/ranksetup/ranksetup_test.cpp b/searchlib/src/tests/ranksetup/ranksetup_test.cpp
index 7a26180eed2..0a20ddb3739 100644
--- a/searchlib/src/tests/ranksetup/ranksetup_test.cpp
+++ b/searchlib/src/tests/ranksetup/ranksetup_test.cpp
@@ -1,6 +1,7 @@
 // Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
 
 #include <vespa/vespalib/testkit/testapp.h>
+#include <vespa/vespalib/util/stringfmt.h>
 #include <vespa/searchlib/common/feature.h>
 
 #include <vespa/searchlib/attribute/attributeguard.h>
@@ -39,6 +40,7 @@ using namespace search::fef;
 using namespace search::features;
 using namespace search::fef::test;
 using search::feature_t;
+using vespalib::make_string_short::fmt;
 
 typedef FeatureNameBuilder FNB;
 
@@ -477,12 +479,22 @@ RankSetupTest::testCompilation()
         rs.setFirstPhaseRank(oss.str());
         EXPECT_TRUE(!rs.compile());
     }
-    { // cycle
+    { // short cycle
         RankSetup rs(_factory, _indexEnv);
         // c(c,4,2) -> c(c,3,2) -> c(c,2,2) -> c(c,1,2) -> c(c,2,2)
         rs.setFirstPhaseRank("chain(cycle,4,2)");
         EXPECT_TRUE(!rs.compile());
     }
+    { // cycle with max back-trace
+        RankSetup rs(_factory, _indexEnv);
+        rs.setFirstPhaseRank(fmt("chain(cycle,%d,2)", BlueprintResolver::MAX_TRACE_SIZE));
+        EXPECT_TRUE(!rs.compile());
+    }
+    { // cycle with max+1 back-trace (skip 2)
+        RankSetup rs(_factory, _indexEnv);
+        rs.setFirstPhaseRank(fmt("chain(cycle,%d,2)", BlueprintResolver::MAX_TRACE_SIZE + 1));
+        EXPECT_TRUE(!rs.compile());
+    }
 }
 
 void RankSetupTest::testRankSetup()
diff --git a/searchlib/src/vespa/searchlib/features/rankingexpressionfeature.cpp b/searchlib/src/vespa/searchlib/features/rankingexpressionfeature.cpp
index 26c61ba6b3c..bf0a731eaef 100644
--- a/searchlib/src/vespa/searchlib/features/rankingexpressionfeature.cpp
+++ b/searchlib/src/vespa/searchlib/features/rankingexpressionfeature.cpp
@@ -295,7 +295,7 @@ RankingExpressionBlueprint::setup(const fef::IIndexEnvironment &env,
         for (const auto &type_error: node_types.errors()) {
             LOG(warning, "type error: %s", type_error.c_str());
         }
-        return fail("rank expression contains type errors: %s\n", script.c_str());
+        return fail("rank expression contains type errors: %s", script.c_str());
     }
     auto compile_issues = CompiledFunction::detect_issues(*rank_function);
     auto interpret_issues = InterpretedFunction::detect_issues(*rank_function);
diff --git a/searchlib/src/vespa/searchlib/fef/blueprintresolver.cpp b/searchlib/src/vespa/searchlib/fef/blueprintresolver.cpp
index c0ca8c857f0..6b4a61e1c0f 100644
--- a/searchlib/src/vespa/searchlib/fef/blueprintresolver.cpp
+++ b/searchlib/src/vespa/searchlib/fef/blueprintresolver.cpp
@@ -11,11 +11,14 @@
 #include <vespa/log/log.h>
 LOG_SETUP(".fef.blueprintresolver");
 
+using vespalib::make_string_short::fmt;
+
 namespace search::fef {
 
 namespace {
 
-static const size_t MAX_TRACE_SIZE = 16;
+constexpr int MAX_TRACE_SIZE = BlueprintResolver::MAX_TRACE_SIZE;
+constexpr int TRACE_SKIP_POS = 10;
 
 using Accept = Blueprint::AcceptInput;
 
@@ -84,22 +87,37 @@ struct Compiler : public Blueprint::DependencyHandler {
     Frame &self() { return resolve_stack.back(); }
     bool failed() const { return !failed_set.empty(); }
 
+    vespalib::string make_trace(bool skip_self) {
+        vespalib::string trace;
+        auto pos = resolve_stack.rbegin();
+        auto end = resolve_stack.rend();
+        if ((pos != end) && skip_self) {
+            ++pos;
+        }
+        size_t i = 0;
+        size_t n = (end - pos);
+        for (; (pos != end); ++pos, ++i) {
+            failed_set.insert(pos->parser.featureName());
+            bool should_trace = (n <= MAX_TRACE_SIZE);
+            should_trace |= (i < TRACE_SKIP_POS);
+            should_trace |= ((end - pos) < (MAX_TRACE_SIZE - TRACE_SKIP_POS));
+            if (should_trace) {
+                trace += fmt("  ... needed by rank feature '%s'\n", pos->parser.featureName().c_str());
+            } else if (i == TRACE_SKIP_POS) {
+                trace += fmt("  (skipped %zu entries)\n", (n - MAX_TRACE_SIZE) + 1);
+            }
+        }
+        return trace;
+    }
+
     FeatureRef fail(const vespalib::string &feature_name, const vespalib::string &reason, bool skip_self = false) {
         if (failed_set.count(feature_name) == 0) {
             failed_set.insert(feature_name);
-            LOG(warning, "invalid rank feature '%s': %s", feature_name.c_str(), reason.c_str());
-            size_t trace_size = 0;
-            for (size_t i = resolve_stack.size(); i > 0; --i) {
-                const auto &frame = resolve_stack[i - 1];
-                failed_set.insert(frame.parser.featureName());
-                if (!skip_self || (&frame != &self())) {
-                    if (++trace_size <= MAX_TRACE_SIZE) {
-                        LOG(warning, "  ... needed by rank feature '%s'", frame.parser.featureName().c_str());
-                    }
-                }
-            }
-            if (trace_size > MAX_TRACE_SIZE) {
-                LOG(warning, "  ... (%zu more)", (trace_size - MAX_TRACE_SIZE));
+            auto trace = make_trace(skip_self);
+            if (trace.empty()) {
+                LOG(warning, "invalid rank feature '%s': %s", feature_name.c_str(), reason.c_str());
+            } else {
+                LOG(warning, "invalid rank feature '%s': %s\n%s", feature_name.c_str(), reason.c_str(), trace.c_str());
             }
         }
         return FeatureRef();
@@ -114,8 +132,8 @@ struct Compiler : public Blueprint::DependencyHandler {
         bool is_object = spec.output_types[ref.output].is_object();
         if (!is_compatible(is_object, accept_type)) {
             return fail(parser.featureName(),
-                        vespalib::make_string("output '%s' has wrong type: was %s, expected %s",
-                                parser.output().c_str(), type_str(is_object), accept_type_str(accept_type)));
+                        fmt("output '%s' has wrong type: was %s, expected %s",
+                            parser.output().c_str(), type_str(is_object), accept_type_str(accept_type)));
         }
         return ref;
     }
@@ -136,8 +154,7 @@ struct Compiler : public Blueprint::DependencyHandler {
                 }
                 spec_list.push_back(self().spec); // keep all feature_map refs valid
             } else {
-                fail(parser.featureName(),
-                     vespalib::make_string("unknown basename: '%s'", parser.baseName().c_str()));
+                fail(parser.featureName(), fmt("unknown basename: '%s'", parser.baseName().c_str()));
             }
         }
     }
@@ -167,8 +184,7 @@ struct Compiler : public Blueprint::DependencyHandler {
         if (new_feature != feature_map.end()) {
             return verify_type(parser, new_feature->second, accept_type);
         }
-        return fail(parser.featureName(),
-                    vespalib::make_string("unknown output: '%s'", parser.output().c_str()));
+        return fail(parser.featureName(), fmt("unknown output: '%s'", parser.output().c_str()));
     }
 
     std::optional<FeatureType> resolve_input(const vespalib::string &feature_name, Accept accept_type) override {
diff --git a/searchlib/src/vespa/searchlib/fef/blueprintresolver.h b/searchlib/src/vespa/searchlib/fef/blueprintresolver.h
index 8fcfb1be86d..60b1eacb803 100644
--- a/searchlib/src/vespa/searchlib/fef/blueprintresolver.h
+++ b/searchlib/src/vespa/searchlib/fef/blueprintresolver.h
@@ -68,7 +68,14 @@ public:
      * problems for 'sane' developers and low enough to avoid stack
      * overflow.
      **/
-    static const uint32_t MAX_DEP_DEPTH = 256;
+    static constexpr uint32_t MAX_DEP_DEPTH = 256;
+
+    /**
+     * The maximum size of back-traces. Longer back-traces will be
+     * logged with skipped entries somewhere in the middle. Exposed
+     * for testing purposes.
+     **/
+    static constexpr int MAX_TRACE_SIZE = 16;
 
 private:
     const BlueprintFactory       &_factory;