Re: [squid-dev] [PATCH] Do not hide important/critical messages

[Eliezer Croitoru]

Thanks!

Eliezer


Eliezer Croitoru
Linux System Administrator
Mobile: +972-5-28704261
Email: elie...@ngtech.co.il


-Original Message-
From: squid-dev [mailto:squid-dev-boun...@lists.squid-cache.org] On Behalf Of 
Amos Jeffries
Sent: Thursday, June 16, 2016 1:24 AM
To: squid-dev@lists.squid-cache.org
Subject: Re: [squid-dev] [PATCH] Do not hide important/critical messages

On 12/04/2016 2:59 a.m., Alex Rousskov wrote:
> On 04/09/2016 10:42 PM, Amos Jeffries wrote:
>> On 29/03/2016 12:44 p.m., Alex Rousskov wrote:
>>> unpatched Squid console only says:
>>>
>>>   2016/03/27 14:19:48.297| SECURITY ALERT: By user agent:
>>>   2016/03/27 14:19:48.297| SECURITY ALERT: on URL: dut70.test:443
>>>
>>> A patched Squid produces the expected three console lines:
>>>
>>>   2016/03/27 15:25:42| SECURITY ALERT: Host header forgery detected...
>>>   2016/03/27 15:25:42| SECURITY ALERT: By user agent:
>>>   2016/03/27 15:25:42| SECURITY ALERT: on URL: dut70.test:443
> 
>>> If this v3.5 patch is accepted in principle, I hope somebody 
>>> volunteers a trunk port (which should not be difficult).
> 
> 
>> This appears to be just a polished implementation of the intended
>> debugs() original design. So in principle its already acceptible.
> 
>> To get into v3.5 it does need to go in through v4 first though.
> 
> 

Now that the v4 port is done and working. Iv've applied this to 3.5 as 
rev.14058.

Amos


___
squid-dev mailing list
squid-dev@lists.squid-cache.org
http://lists.squid-cache.org/listinfo/squid-dev

___
squid-dev mailing list
squid-dev@lists.squid-cache.org
http://lists.squid-cache.org/listinfo/squid-dev

Re: [squid-dev] [PATCH] Do not hide important/critical messages

[Amos Jeffries]

On 12/04/2016 2:59 a.m., Alex Rousskov wrote:
> On 04/09/2016 10:42 PM, Amos Jeffries wrote:
>> On 29/03/2016 12:44 p.m., Alex Rousskov wrote:
>>> unpatched Squid console only says:
>>>
>>>   2016/03/27 14:19:48.297| SECURITY ALERT: By user agent:
>>>   2016/03/27 14:19:48.297| SECURITY ALERT: on URL: dut70.test:443
>>>
>>> A patched Squid produces the expected three console lines:
>>>
>>>   2016/03/27 15:25:42| SECURITY ALERT: Host header forgery detected...
>>>   2016/03/27 15:25:42| SECURITY ALERT: By user agent:
>>>   2016/03/27 15:25:42| SECURITY ALERT: on URL: dut70.test:443
> 
>>> If this v3.5 patch is accepted in principle, I hope somebody volunteers
>>> a trunk port (which should not be difficult).
> 
> 
>> This appears to be just a polished implementation of the intended
>> debugs() original design. So in principle its already acceptible.
> 
>> To get into v3.5 it does need to go in through v4 first though.
> 
> 

Now that the v4 port is done and working. Iv've applied this to 3.5 as
rev.14058.

Amos


___
squid-dev mailing list
squid-dev@lists.squid-cache.org
http://lists.squid-cache.org/listinfo/squid-dev

Re: [squid-dev] [PATCH] Do not hide important/critical messages

[Amos Jeffries]

On 20/05/2016 3:36 a.m., Eduard Bagdasaryan wrote:
> Hello,
> 
> 2016-05-19 16:54 GMT+03:00 Amos Jeffries :
>> Thanks. But ... I just tried to apply this and got lots of rejects in
>> Debugs.h and debug.cc on the latest trunk.
> 
> Reworked against the latest r14673, sorry. The previous version
> was for r14667, I did not expect the things moved forward so quickly...
> 

Thanks. Applied as trunk rev.14678.

Amos

___
squid-dev mailing list
squid-dev@lists.squid-cache.org
http://lists.squid-cache.org/listinfo/squid-dev

Re: [squid-dev] [PATCH] Do not hide important/critical messages

[Amos Jeffries]

On 19/05/2016 10:01 p.m., Eduard Bagdasaryan wrote:
> Hello,
> 
> This is a trunk port for Alex's v3.5 reentrant debugging fix
> .
> 

Thanks. But ... I just tried to apply this and got lots of rejects in
Debugs.h and debug.cc on the latest trunk.

Amos

___
squid-dev mailing list
squid-dev@lists.squid-cache.org
http://lists.squid-cache.org/listinfo/squid-dev

[squid-dev] [PATCH] Do not hide important/critical messages

[Eduard Bagdasaryan]

Hello,

This is a trunk port for Alex's v3.5 reentrant debugging fix 
.


Regards,
Eduard.
Do not allow low-level debugging to hide important/critical messages.

Removed debugs() side effects that inadvertently resulted in some
important/critical messages logged at the wrong debugging level and,
hence, becoming invisible to the admin. The removed side effects set the
"current" debugging level when a debugs() parameter called a function
that also called debugs(). The last nested debugs() called affected the
level of all debugs() still in progress!

Related changes:

* Reentrant debugging messages no longer clobber parent messages. Each
  debugging message is logged separately, in the natural order of
  debugs() calls that would have happened if debugs() were a function
  (that gets already evaluated arguments) and not a macro (that
  evaluates its arguments in the middle of the call). This order is
  "natural" because good macros work like functions from the caller
  point of view.

* Assertions hit while evaluating debugs() parameters are now logged
  instead of being lost with the being-built debugs() log line.

* 10-20% faster debugs() performance because we no longer allocate a new
  std::ostringstream buffer for the vast majority of debugs() calls.
  Only reentrant calls get a new buffer.

* Removed old_debug(), addressing an old "needs to die" to-do.

* Removed do_debug() that changed debugging level while testing whether
  debugging is needed. Use side-effect-free Debug::Enabled() instead.

Also removed the OutStream wrapper class. The wrapper was added in trunk 
revision 13767 that promised to (but did not?) MemPool the debug output
buffers. We no longer "new" the buffer stream so a custom new() method
would be unused. Besides, the r13767 explanation implied that providing
a Child::new() method would somehow overwrite Parent::allocator_type,
which did not compute for me. Finally, Squid "new"s other allocator-
enabled STL objects without overriding their new methods so either the
same problem is still there or it did not exist (or was different?).

Also removed Debug::xassert() because the debugs() assertions now work
OK without that hack.

=== modified file 'src/Debug.h'
--- src/Debug.h	2016-01-01 00:12:18 +
+++ src/Debug.h	2016-05-19 08:48:18 +
@@ -25,153 +25,164 @@
 #if PURIFY
 #define assert(EX) ((void)0)
 #elif defined(NODEBUG)
 #define assert(EX) ((void)0)
 #elif STDC_HEADERS
 #define assert(EX)  ((EX)?((void)0):xassert( # EX , __FILE__, __LINE__))
 #else
 #define assert(EX)  ((EX)?((void)0):xassert("EX", __FILE__, __LINE__))
 #endif
 
 /* context-based debugging, the actual type is subject to change */
 typedef int Ctx;
 Ctx ctx_enter(const char *descr);
 void ctx_exit(Ctx ctx);
 
 /* defined debug section limits */
 #define MAX_DEBUG_SECTIONS 100
 
 /* defined names for Debug Levels */
 #define DBG_CRITICAL0   /**< critical messages always shown when they occur */
 #define DBG_IMPORTANT   1   /**< important messages always shown when their section is being checked */
 /* levels 2-8 are still being discussed amongst the developers */
 #define DBG_DATA9   /**< output is a large data dump only necessary for advanced debugging */
 
 #define DBG_PARSE_NOTE(x) (opt_parse_cfg_only?0:(x)) /**< output is always to be displayed on '-k parse' but at level-x normally. */
 
 class Debug
 {
 
 public:
+/// meta-information for debugs() or a similar debugging call
+class Context
+{
+public:
+Context(const int aSectionLevel, const int aLevel);
+
+int level; ///< minimum debugging level required by the debugs() call
+int sectionLevel; ///< maximum debugging level allowed during the call
+
+private:
+friend class Debug;
+void rewind(const int aSection, const int aLevel);
+void formatStream();
+Context *upper; ///< previous or parent record in nested debugging calls
+std::ostringstream buf; ///< debugs() output sink
+};
+
+/// whether debugging the given section and the given level produces output
+static bool Enabled(const int section, const int level)
+{
+return level <= Debug::Levels[section];
+}
+
 static char *debugOptions;
 static char *cache_log;
 static int rotateNumber;
 static int Levels[MAX_DEBUG_SECTIONS];
-static int level; ///< minimum debugging level required by debugs() call
-static int sectionLevel; ///< maximum debugging level allowed now
 static int override_X;
 static int log_stderr;
 static bool log_syslog;
 
-static std::ostream ();
-static void finishDebug();
 static void parseOptions(char const *);
 
+/// minimum level required by the current debugs() call
+static int Level() { return Current ? Current->level : 1; }
+/// maximum level currently allowed
+static int SectionLevel() { return Current ? Current->sectionLevel : 1; }

Re: [squid-dev] [PATCH] Do not hide important/critical messages

[Alex Rousskov]

On 04/09/2016 10:42 PM, Amos Jeffries wrote:
> On 29/03/2016 12:44 p.m., Alex Rousskov wrote:
>> unpatched Squid console only says:
>>
>>   2016/03/27 14:19:48.297| SECURITY ALERT: By user agent:
>>   2016/03/27 14:19:48.297| SECURITY ALERT: on URL: dut70.test:443
>>
>> A patched Squid produces the expected three console lines:
>>
>>   2016/03/27 15:25:42| SECURITY ALERT: Host header forgery detected...
>>   2016/03/27 15:25:42| SECURITY ALERT: By user agent:
>>   2016/03/27 15:25:42| SECURITY ALERT: on URL: dut70.test:443

>> If this v3.5 patch is accepted in principle, I hope somebody volunteers
>> a trunk port (which should not be difficult).


> This appears to be just a polished implementation of the intended
> debugs() original design. So in principle its already acceptible.

> To get into v3.5 it does need to go in through v4 first though.


Sounds good to me. Does anybody want to volunteer to port these fixes to
trunk?


Thank you,

Alex.

___
squid-dev mailing list
squid-dev@lists.squid-cache.org
http://lists.squid-cache.org/listinfo/squid-dev

Re: [squid-dev] [PATCH] Do not hide important/critical messages

[Amos Jeffries]

On 29/03/2016 12:44 p.m., Alex Rousskov wrote:
> Hello,
> 
> While working on Squid bug 4465 (Header forgery detection leads to
> crash), I noticed that Squid may hide important/critical debugs()
> messages from the admin if those messages are assembled using code that
> also uses debugs(). For example, unpatched Squid console only says:
> 
>   2016/03/27 14:19:48.297| SECURITY ALERT: By user agent:
>   2016/03/27 14:19:48.297| SECURITY ALERT: on URL: dut70.test:443
> 
> A patched Squid produces the expected three console lines:
> 
>   2016/03/27 15:25:42| SECURITY ALERT: Host header forgery detected...
>   2016/03/27 15:25:42| SECURITY ALERT: By user agent:
>   2016/03/27 15:25:42| SECURITY ALERT: on URL: dut70.test:443
> 
> 
> The underlying debugs() bug leads to several rather confusing problems.
> For example, the unpatched output quoted above has millisecond
> timestamps that are not supposed to be there; the hidden lines may
> actually be logged into cache.log (but not on the console/stderr or
> system log). It took several patch rewrites and many tests to better
> understand these side effects (which explains, in part, why the patch
> has more cleanup pieces than are strictly necessary to fix the bug in
> the subject line).
> 
> The attached v3.5 patch fixes the underlying bug and has several
> positive side-effects such as faster debugs() performance, no clobbered
> messages, and cleaner code. Please see patch preamble for a complete
> list of known side effects.
> 
> If this v3.5 patch is accepted in principle, I hope somebody volunteers
> a trunk port (which should not be difficult).
> 

This appears to be just a polished implementation of the intended
debugs() original design. So in principle its already acceptible.

To get into v3.5 it does need to go in through v4 first though. We don't
want a repeat of the 2.x forking situation.

Amos

___
squid-dev mailing list
squid-dev@lists.squid-cache.org
http://lists.squid-cache.org/listinfo/squid-dev

[squid-dev] [PATCH] Do not hide important/critical messages

[Alex Rousskov]

Hello,

While working on Squid bug 4465 (Header forgery detection leads to
crash), I noticed that Squid may hide important/critical debugs()
messages from the admin if those messages are assembled using code that
also uses debugs(). For example, unpatched Squid console only says:

  2016/03/27 14:19:48.297| SECURITY ALERT: By user agent:
  2016/03/27 14:19:48.297| SECURITY ALERT: on URL: dut70.test:443

A patched Squid produces the expected three console lines:

  2016/03/27 15:25:42| SECURITY ALERT: Host header forgery detected...
  2016/03/27 15:25:42| SECURITY ALERT: By user agent:
  2016/03/27 15:25:42| SECURITY ALERT: on URL: dut70.test:443


The underlying debugs() bug leads to several rather confusing problems.
For example, the unpatched output quoted above has millisecond
timestamps that are not supposed to be there; the hidden lines may
actually be logged into cache.log (but not on the console/stderr or
system log). It took several patch rewrites and many tests to better
understand these side effects (which explains, in part, why the patch
has more cleanup pieces than are strictly necessary to fix the bug in
the subject line).

The attached v3.5 patch fixes the underlying bug and has several
positive side-effects such as faster debugs() performance, no clobbered
messages, and cleaner code. Please see patch preamble for a complete
list of known side effects.

If this v3.5 patch is accepted in principle, I hope somebody volunteers
a trunk port (which should not be difficult).


Thank you,

Alex.
P.S. This patch is not intended to fix Squid bug 4465.
Do not allow low-level debugging to hide important/critical messages.

Removed debugs() side effects that inadvertently resulted in some
important/critical messages logged at the wrong debugging level and,
hence, becoming invisible to the admin. The removed side effects set the
"current" debugging level when a debugs() parameter called a function
that also called debugs(). The last nested debugs() called affected the
level of all debugs() still in progress!

Related changes:

* Reentrant debugging messages no longer clobber parent messages. Each
  debugging message is logged separately, in the natural order of
  debugs() calls that would have happened if debugs() were a function
  (that gets already evaluated arguments) and not a macro (that
  evaluates its arguments in the middle of the call). This order is
  "natural" because good macros work like functions from the caller
  point of view.

* Assertions hit while evaluating debugs() parameters are now logged
  instead of being lost with the being-built debugs() log line.

* 10-20% faster debugs() performance because we no longer allocate a new
  std::ostringstream buffer for the vast majority of debugs() calls.
  Only reentrant calls get a new buffer.

* Removed old_debug(), addressing an old "needs to die" to-do.

* Removed do_debug() that changed debugging level while testing whether
  debugging is needed. Use side-effect-free Debug::Enabled() instead.

Also removed the OutStream wrapper class. The wrapper was added in v3.5
revision 13698 that promised to (but did not?) MemPool the debug output
buffers. We no longer "new" the buffer stream so a custom new() method
would be unused. Besides, the r13698 explanation implied that providing
a Child::new() method would somehow overwrite Parent::allocator_type,
which did not compute for me. Finally, Squid "new"s other allocator-
enabled STL objects without overriding their new methods so either the
same problem is still there or it did not exist (or was different?).

Also removed Debug::xassert() because the debugs() assertions now work
OK without that hack.

=== modified file 'src/Debug.h'
--- src/Debug.h	2016-01-01 00:14:27 +
+++ src/Debug.h	2016-03-27 17:56:21 +
@@ -32,130 +32,139 @@
 /* context-based debugging, the actual type is subject to change */
 typedef int Ctx;
 Ctx ctx_enter(const char *descr);
 void ctx_exit(Ctx ctx);
 
 /* defined debug section limits */
 #define MAX_DEBUG_SECTIONS 100
 
 /* defined names for Debug Levels */
 #define DBG_CRITICAL0   /**< critical messages always shown when they occur */
 #define DBG_IMPORTANT   1   /**< important messages always shown when their section is being checked */
 /* levels 2-8 are still being discussed amongst the developers */
 #define DBG_DATA9   /**< output is a large data dump only necessary for advanced debugging */
 
 #define DBG_PARSE_NOTE(x) (opt_parse_cfg_only?0:(x)) /**< output is always to be displayed on '-k parse' but at level-x normally. */
 
 class Debug
 {
 
 public:
+/// meta-information for debugs() or a similar debugging call
+class Context
+{
+public:
+Context(const int aSectionLevel, const int aLevel);
+
+int level; ///< minimum debugging level required by the debugs() call
+int sectionLevel; ///< maximum debugging level allowed during the call
+
+private:
+friend class Debug;
+void rewind(const int