Fix and improve annotation reporting (#1516)

We just wanted to remove legacy printf()-like calls from Notes.cc, but
realized that finding correct replacement for that code is complicated
because some of the calls were broken, and the true meaning or purpose
of the affected annotation reporting methods was elusive. This change
combines several related fixes and improvements detailed below.

### Fix reporting method names and their descriptions

Humans could not easily figure out the difference between Note::dump(),
Note::toString(), Notes::dump(), Notes::toString(), and
NotePairs::toString() methods, especially since Note and Notes classes
had both, implying some important difference. The toString() name is
very generic. The dump() name is used (differently) in Configuration
code and ACL class hierarchy; these classes are used by that code, but
they do not belong to that hierarchy. Bugs and the variety of
annotation-related use cases increased doubts and confusion.

The new task/format-specific names for Note and Notes methods fix this.

### Fix annotate_client and annotate_transaction mgr:config reporting

```diff
-acl markAsX annotate_client name1: value1
-name2: value2a,value2b
-
+acl markAsX annotate_client name1=value1 name2=value2a,value2b
```

Multi-name annotations were split across several lines and used an
incorrect name/value separator. The "acl" directive line was followed by
an extra new line.

### Fix note directive mgr:config reporting

```diff

-note name1 "value1a,value1b"(note name1... line)
-
-note name2 "value2"(note name2... line)
-
+note name1 "value1a,value1b"
+note name2 "value2" fromTrustedClient toTrustedServer
```

Each "note" directive was followed by bogus "(note...)" suffix instead
of ACL names (if any). The "note" directive line was followed by an
extra new line.

### Improve debugging of annotations in helper responses

```diff
- ... externalAclHandleReply: reply={result=OK, notes={tag: 1; x_: Y }}
+ ... externalAclHandleReply: reply={result=OK, notes={tag=1 x_=Y }}
```

The contents of old notes{...} did not match what helpers were sending.
The new format matches helper output in all simple cases (at least).

diff --git a/src/Notes.cc b/src/Notes.cc
index cba2c7187abe3b6e2f421796a8e758c09208cb81..207824fc42b90a905732079af109c3cafb8f5237 100644 (file)
--- a/src/Notes.cc
+++ b/src/Notes.cc
@@ -10,6 +10,7 @@
 #include "AccessLogEntry.h"
 #include "acl/FilledChecklist.h"
 #include "acl/Gadgets.h"
+#include "acl/Tree.h"
 #include "client_side.h"
 #include "ConfigParser.h"
 #include "globals.h"
@@ -24,6 +25,7 @@
 #include "StrList.h"
 
 #include <algorithm>
+#include <ostream>
 #include <string>
 
 Note::Value::~Value()
@@ -39,9 +41,7 @@ Note::Value::Value(const char *aVal, const bool quoted, const char *descr, const
         valueFormat = new Format::Format(descr ? descr : "Notes");
         if (!valueFormat->parse(theValue.c_str())) {
             delete valueFormat;
-            SBuf exceptionMsg;
-            exceptionMsg.Printf("failed to parse annotation value %s", theValue.c_str());
-            throw TexcHere(exceptionMsg.c_str());
+            throw TextException(ToSBuf("failed to parse annotation value ", theValue), Here());
         }
     }
 }
@@ -105,24 +105,34 @@ Note::updateNotePairs(NotePairs::Pointer pairs, const CharacterSet *delimiters,
 }
 
 void
-Note::dump(StoreEntry *entry, const char *k)
+Note::printAsNoteDirective(StoreEntry * const entry, const char * const directiveName) const
 {
+    PackableStream os(*entry);
     for (const auto &v: values) {
-        storeAppendPrintf(entry, "%s %.*s %s",
-                          k, key().length(), key().rawContent(), ConfigParser::QuoteString(SBufToString(v->value())));
-        dump_acl_list(entry, v->aclList);
-        storeAppendPrintf(entry, "\n");
+        os << directiveName << ' ' << key() << ' ' << ConfigParser::QuoteString(SBufToString(v->value()));
+        if (v->aclList) {
+            // TODO: Use Acl::dump() after fixing the XXX in dump_acl_list().
+            for (const auto &item: v->aclList->treeDump("", &Acl::AllowOrDeny)) {
+                if (item.isEmpty()) // treeDump("") adds this prefix
+                    continue;
+                if (item.cmp("\n") == 0) // treeDump() adds this suffix
+                    continue;
+                os << ' ' << item; // ACL name
+            }
+        }
+        os << '\n';
     }
 }
 
-SBuf
-Note::toString(const char *sep) const
+void
+Note::printAsAnnotationAclParameters(std::ostream &os) const
 {
-    SBuf result;
-    for (const auto &val: values)
-        result.appendf("%.*s: %.*s%s", key().length(), key().rawContent(),
-                       val->value().length(), val->value().rawContent(), sep);
-    return result;
+    auto separator = "";
+    for (const auto &v: values) {
+        os << separator;
+        os << key() << (v->method() == Value::mhReplace ? "=" : "+=") << v->value();
+        separator = " ";
+    }
 }
 
 const Notes::Keys &
@@ -252,20 +262,21 @@ Notes::updateNotePairs(NotePairs::Pointer pairs, const CharacterSet *delimiters,
 }
 
 void
-Notes::dump(StoreEntry *entry, const char *key)
+Notes::printAsNoteDirectives(StoreEntry *entry, const char * const directiveName) const
 {
     for (const auto &n: notes)
-        n->dump(entry, key);
+        n->printAsNoteDirective(entry, directiveName);
 }
 
-const char *
-Notes::toString(const char *sep) const
+void
+Notes::printAsAnnotationAclParameters(std::ostream &os) const
 {
-    static SBuf result;
-    result.clear();
-    for (const auto &note: notes)
-        result.append(note->toString(sep));
-    return result.isEmpty() ? nullptr : result.c_str();
+    const char *separator = "";
+    for (const auto &note: notes) {
+        os << separator;
+        note->printAsAnnotationAclParameters(os);
+        separator = " ";
+    }
 }
 
 bool
@@ -282,15 +293,11 @@ NotePairs::find(SBuf &resultNote, const char *noteKey, const char *sep) const
     return resultNote.length();
 }
 
-const char *
-NotePairs::toString(const char *sep) const
+void
+NotePairs::print(std::ostream &os, const char * const nameValueSeparator, const char * const entryTerminator) const
 {
-    static SBuf result;
-    result.clear();
     for (const auto &e: entries)
-        result.appendf("%.*s: %.*s%s", e->name().length(), e->name().rawContent(),
-                       e->value().length(), e->value().rawContent(), sep);
-    return result.isEmpty() ? nullptr : result.c_str();
+        os << e->name() << nameValueSeparator << e->value() << entryTerminator;
 }
 
 const char *

diff --git a/src/Notes.h b/src/Notes.h
index 0c6229e23dbe92db3a404a513da639206f59749d..18cd9f71ca21640b548b27c455852979259084bd 100644 (file)
--- a/src/Notes.h
+++ b/src/Notes.h
@@ -11,10 +11,12 @@
 
 #include "acl/forward.h"
 #include "base/RefCount.h"
+#include "sbuf/forward.h"
 #include "format/Format.h"
 #include "mem/forward.h"
 #include "SquidString.h"
 
+#include <iosfwd>
 #include <string>
 #include <vector>
 
@@ -89,11 +91,13 @@ public:
     bool match(HttpRequest *request, HttpReply *reply, const AccessLogEntryPointer &al, SBuf &matched);
     const SBuf &key() const { return theKey; }
     void updateNotePairs(NotePairsPointer pairs, const CharacterSet *delimiters, const AccessLogEntryPointer &al);
-    /// Dump the single Note to the given StoreEntry object.
-    void dump(StoreEntry *entry, const char *key);
-    /// For the key and all its Values compile a string of
-    /// "Key: Value" pairs separated by sep string.
-    SBuf toString(const char *sep) const;
+
+    /// Prints key and value(s) using a "note" directive format (including directive name).
+    void printAsNoteDirective(StoreEntry *, const char *directiveName) const;
+
+    /// Prints using "annotate_transaction acl parameter" format, one key=value
+    /// or key+=value parameter per stored value.
+    void printAsAnnotationAclParameters(std::ostream &) const;
 
 private:
     SBuf theKey; ///< The note key
@@ -126,8 +130,9 @@ public:
     /// Parses an annotate line with "key=value" or "key+=value" formats.
     void parseKvPair();
 
-    /// Dump the notes list to the given StoreEntry object.
-    void dump(StoreEntry *entry, const char *name);
+    /// Prints notes using "note" squid.conf directive format, one directive per stored note.
+    void printAsNoteDirectives(StoreEntry *, const char *directiveName) const;
+
     /// clean the notes list
     void clean() { notes.clear(); }
 
@@ -137,9 +142,11 @@ public:
     iterator end() { return notes.end(); }
     /// \returns true if the notes list is empty
     bool empty() const { return notes.empty(); }
-    /// Convert Notes list to a string consist of "Key: Value"
-    /// entries separated by sep string.
-    const char *toString(const char *sep = "\r\n") const;
+
+    /// print notes using "annotate_transaction acl parameters" format, one
+    /// key=value parameter per note
+    void printAsAnnotationAclParameters(std::ostream &) const;
+
     void updateNotePairs(NotePairsPointer pairs, const CharacterSet *delimiters,
                          const AccessLogEntryPointer &al);
 private:
@@ -245,9 +252,9 @@ public:
     /// \returns true if the key/value pair is already stored
     bool hasPair(const SBuf &key, const SBuf &value) const;
 
-    /// Convert NotePairs list to a string consist of "Key: Value"
-    /// entries separated by sep string.
-    const char *toString(const char *sep = "\r\n") const;
+    /// Reports all entries (if any), printing exactly four items for each:
+    /// entry name, nameValueSeparator, entry value, and entry terminator.
+    void print(std::ostream &os, const char *nameValueSeparator, const char *entryTerminator) const;
 
     /// \returns true if there are not entries in the list
     bool empty() const {return entries.empty();}

diff --git a/src/acl/AnnotationData.cc b/src/acl/AnnotationData.cc
index ba69f77ee1d24e268fab234f69a6b62a96618844..17f1ef33bace16281f8fff0750ea2af003554c3c 100644 (file)
--- a/src/acl/AnnotationData.cc
+++ b/src/acl/AnnotationData.cc
@@ -15,6 +15,7 @@
 #include "debug/Stream.h"
 #include "format/Format.h"
 #include "sbuf/Algorithms.h"
+#include "sbuf/Stream.h"
 
 ACLAnnotationData::ACLAnnotationData()
     : notes(new Notes("annotation_data")) {}
@@ -22,10 +23,12 @@ ACLAnnotationData::ACLAnnotationData()
 SBufList
 ACLAnnotationData::dump() const
 {
-    SBufList sl;
-    if (const char *strNotes = notes->toString())
-        sl.push_back(SBuf(strNotes));
-    return sl;
+    if (notes->empty())
+        return SBufList();
+
+    SBufStream os;
+    notes->printAsAnnotationAclParameters(os);
+    return SBufList{os.buf()};
 }
 
 void

diff --git a/src/cache_cf.cc b/src/cache_cf.cc
index 17b961ffa7b980e46bf8ea4a6bd27fee41e47710..1e570c4cbba2d1ee4e811499acb73471c7fa1636 100644 (file)
--- a/src/cache_cf.cc
+++ b/src/cache_cf.cc
@@ -4580,7 +4580,7 @@ static void parse_note(Notes *notes)
 
 static void dump_note(StoreEntry *entry, const char *name, Notes &notes)
 {
-    notes.dump(entry, name);
+    notes.printAsNoteDirectives(entry, name);
 }
 
 static void free_note(Notes *notes)

diff --git a/src/format/Format.cc b/src/format/Format.cc
index 892c5f01ec8d63dae5a27875008a7366641e4d0e..abd919c5aaeaf67b01f521aff826d142016dafda 100644 (file)
--- a/src/format/Format.cc
+++ b/src/format/Format.cc
@@ -1407,16 +1407,20 @@ Format::Format::assemble(MemBuf &mb, const AccessLogEntry::Pointer &al, int logS
                 out = sb.c_str();
                 quote = 1;
             } else {
+                // No specific annotation requested. Report all annotations.
+
                 // if no argument given use default "\r\n" as notes separator
                 const char *separator = fmt->data.string ? tmp : "\r\n";
+                SBufStream os;
 #if USE_ADAPTATION
                 Adaptation::History::Pointer ah = al->request ? al->request->adaptHistory() : Adaptation::History::Pointer();
-                if (ah && ah->metaHeaders && !ah->metaHeaders->empty())
-                    sb.append(ah->metaHeaders->toString(separator));
+                if (ah && ah->metaHeaders)
+                    ah->metaHeaders->print(os, ": ", separator);
 #endif
-                if (al->notes && !al->notes->empty())
-                    sb.append(al->notes->toString(separator));
+                if (al->notes)
+                    al->notes->print(os, ": ", separator);
 
+                sb = os.buf();
                 out = sb.c_str();
                 quote = 1;
             }

diff --git a/src/helper/Reply.cc b/src/helper/Reply.cc
index 083672cfa73fe7923df84bdbbc50d3c00e5fa74e..93cd5c84322409740939156b7cf72540ec525415 100644 (file)
--- a/src/helper/Reply.cc
+++ b/src/helper/Reply.cc
@@ -277,7 +277,11 @@ Helper::operator <<(std::ostream &os, const Reply &r)
     // dump the helper key=pair "notes" list
     if (!r.notes.empty()) {
         os << ", notes={";
-        os << r.notes.toString("; ");
+        // This simple format matches what most helpers use and is sufficient
+        // for debugging nearly any helper response, but the result differs from
+        // raw helper responses when the helper quotes values or escapes special
+        // characters. See also: Helper::Reply::parseResponseKeys().
+        r.notes.print(os, "=", " ");
         os << "}";
     }