Change threading formatter errors to warnings.

This change standardizes threading formatter error handling and moves
the remaining error calls to be warnings instead.

This is in line with already existing code - in most cases warnings were
raised, only a few cases raised errors. These cases do not differ
significantly from other cases in which warnings are raised.

This also fixes GH-692, in which misformatted lines prevent future file
parsing.

This commit also moves the FailWarn method that is used by both the
config and the ascii reader up to the ReaderBackend. Furthermore it
makes the Warning method of ReaderBackend respect the warning
suppression that is introduced by the FailWarn method.

src/input/ReaderBackend.cc

@@ -336,8 +336,26 @@ void ReaderBackend::Info(const char* msg)
 	MsgThread::Info(msg);
 	}
 
+void ReaderBackend::FailWarn(bool is_error, const char *msg, bool suppress_future)
+	{
+	if ( is_error )
+		Error(msg);
+	else
+		{
+		// suppress error message when we are already in error mode.
+		// There is no reason to repeat it every second.
+		if ( ! suppress_warnings )
+			Warning(msg);
+
+		if ( suppress_future )
+			suppress_warnings = true;
+		}
+	}
 void ReaderBackend::Warning(const char* msg)
 	{
+	if ( suppress_warnings )
+		return;
+
 	SendOut(new ReaderErrorMessage(frontend, ReaderErrorMessage::WARNING, msg));
 	MsgThread::Warning(msg);
 	}

src/input/ReaderBackend.h

@@ -138,7 +138,7 @@ public:
 	/**
 	 * One-time initialization of the reader to define the input source.
 	 *
-	 * @param @param info Meta information for the writer.
+	 * @param info Meta information for the writer.
 	 *
 	 * @param num_fields Number of fields contained in \a fields.
 	 *
@@ -184,11 +184,34 @@ public:
 	 */
 	int NumFields() const	{ return num_fields; }
 
+	/**
+	 * Convenience function that calls Warning or Error, depending on the
+	 * is_error parameter. In case of a warning, setting suppress_future to
+	 * true will suppress all future warnings until StopWarningSuppression()
+	 * is called.
+	 *
+	 * @param is_error If set to true, an error is generated. Else a warning
+	 *                 is generate.
+	 *
+	 * @param msg The error/warning message.
+	 *
+	 * @param suppress_future If set to true, future warnings are suppressed
+	 *                        until StopWarningSuppression is called.
+	 */
+	void FailWarn(bool is_error, const char *msg, bool suppress_future = false);
+
+	inline void StopWarningSuppression() { suppress_warnings = false; };
+
 	// Overridden from MsgThread.
 	bool OnHeartbeat(double network_time, double current_time) override;
 	bool OnFinish(double network_time) override;
 
 	void Info(const char* msg) override;
+
+	/**
+	 * Reports a warning in the child thread. For input readers, warning suppression
+	 * that is caused by calling FailWarn() is respected by the Warning function.
+	 */
 	void Warning(const char* msg) override;
 
 	/**
@@ -348,6 +371,9 @@ private:
 	const threading::Field* const * fields; // raw mapping
 
 	bool disabled;
+	// this is an internal indicator in case the read is currently in a failed state
+	// it's used to suppress duplicate error messages.
+	bool suppress_warnings = false;
 };
 
 }

src/input/readers/ascii/Ascii.cc

@@ -50,7 +50,6 @@ Ascii::Ascii(ReaderFrontend *frontend) : ReaderBackend(frontend)
 	{
 	mtime = 0;
 	ino = 0;
-	suppress_warnings = false;
 	fail_on_file_problem = false;
 	fail_on_invalid_lines = false;
 	}
@@ -65,7 +64,7 @@ void Ascii::DoClose()
 
 bool Ascii::DoInit(const ReaderInfo& info, int num_fields, const Field* const* fields)
 	{
-	suppress_warnings = false;
+	StopWarningSuppression();
 
 	separator.assign( (const char*) BifConst::InputAscii::separator->Bytes(),
 	                 BifConst::InputAscii::separator->Len());
@@ -119,21 +118,6 @@ bool Ascii::DoInit(const ReaderInfo& info, int num_fields, const Field* const* f
 	return DoUpdate();
 	}
 
-void Ascii::FailWarn(bool is_error, const char *msg, bool suppress_future)
-	{
-	if ( is_error )
-		Error(msg);
-	else
-		{
-		// suppress error message when we are already in error mode.
-		// There is no reason to repeat it every second.
-		if ( ! suppress_warnings )
-			Warning(msg);
-
-		if ( suppress_future )
-			suppress_warnings = true;
-		}
-	}
 
 bool Ascii::OpenFile()
 	{
@@ -173,7 +157,7 @@ bool Ascii::OpenFile()
 		return ! fail_on_file_problem;
 		}
 
-	suppress_warnings = false;
+	StopWarningSuppression();
 	return true;
 	}
 
@@ -309,7 +293,7 @@ bool Ascii::DoUpdate()
 			// is to suppress an extra warning that we'd otherwise get on the initial
 			// inode assignment.
 			if ( ino != 0 )
-				suppress_warnings = false;
+				StopWarningSuppression();
 
 			mtime = sb.st_mtime;
 			ino = sb.st_ino;

src/input/readers/ascii/Ascii.h

@@ -56,10 +56,6 @@ private:
 	bool ReadHeader(bool useCached);
 	bool GetLine(string& str);
 	bool OpenFile();
-	// Call Warning or Error, depending on the is_error boolean.
-	// In case of a warning, setting suppress_future to true will suppress all future warnings
-	// (by setting suppress_warnings to true, until suppress_warnings is set back to false)
-	void FailWarn(bool is_error, const char *msg, bool suppress_future = false);
 
 	ifstream file;
 	time_t mtime;
@@ -85,10 +81,6 @@ private:
 	bool fail_on_file_problem;
 	string path_prefix;
 
-	// this is an internal indicator in case the read is currently in a failed state
-	// it's used to suppress duplicate error messages.
-	bool suppress_warnings;
-
 	std::unique_ptr<threading::formatter::Formatter> formatter;
 };
 

src/input/readers/config/Config.cc

@@ -24,7 +24,6 @@ Config::Config(ReaderFrontend *frontend) : ReaderBackend(frontend)
 	{
 	mtime = 0;
 	ino = 0;
-	suppress_warnings = false;
 	fail_on_file_problem = false;
 
 	// find all option names and their types.
@@ -91,26 +90,10 @@ bool Config::OpenFile()
 		return ! fail_on_file_problem;
 		}
 
-	suppress_warnings = false;
+	StopWarningSuppression();
 	return true;
 	}
 
-void Config::FailWarn(bool is_error, const char *msg, bool suppress_future)
-	{
-	if ( is_error )
-		Error(msg);
-	else
-		{
-		// suppress error message when we are already in error mode.
-		// There is no reason to repeat it every second.
-		if ( ! suppress_warnings )
-			Warning(msg);
-
-		if ( suppress_future )
-			suppress_warnings = true;
-		}
-	}
-
 bool Config::GetLine(string& str)
 	{
 	while ( getline(file, str) )
@@ -155,7 +138,7 @@ bool Config::DoUpdate()
 			// is to suppress an extra warning that we'd otherwise get on the initial
 			// inode assignment.
 			if ( ino != 0 )
-				suppress_warnings = false;
+				StopWarningSuppression();
 
 			mtime = sb.st_mtime;
 			ino = sb.st_ino;

src/input/readers/config/Config.h

@@ -39,19 +39,12 @@ protected:
 private:
 	bool GetLine(string& str);
 	bool OpenFile();
-	// Call Warning or Error, depending on the is_error boolean.
-	// In case of a warning, setting suppress_future to true will suppress all future warnings
-	// (by setting suppress_warnings to true, until suppress_warnings is set back to false)
-	void FailWarn(bool is_error, const char *msg, bool suppress_future = false);
 
 	ifstream file;
 	time_t mtime;
 	ino_t ino;
 
 	bool fail_on_file_problem;
-	// this is an internal indicator in case the read is currently in a failed state
-	// it's used to suppress duplicate error messages.
-	bool suppress_warnings;
 
 	string set_separator;
 	string empty_field;

src/threading/Formatter.cc

@@ -55,7 +55,7 @@ TransportProto Formatter::ParseProto(const string &proto) const
 	else if ( proto == "icmp" )
 		return TRANSPORT_ICMP;
 
-	thread->Error(thread->Fmt("Tried to parse invalid/unknown protocol: %s", proto.c_str()));
+	thread->Warning(thread->Fmt("Tried to parse invalid/unknown protocol: %s", proto.c_str()));
 
 	return TRANSPORT_UNKNOWN;
 	}
@@ -72,7 +72,7 @@ threading::Value::addr_t Formatter::ParseAddr(const string &s) const
 
 		if ( inet_aton(s.c_str(), &(val.in.in4)) <= 0 )
 			{
-			thread->Error(thread->Fmt("Bad address: %s", s.c_str()));
+			thread->Warning(thread->Fmt("Bad address: %s", s.c_str()));
 			memset(&val.in.in4.s_addr, 0, sizeof(val.in.in4.s_addr));
 			}
 		}
@@ -82,7 +82,7 @@ threading::Value::addr_t Formatter::ParseAddr(const string &s) const
 		val.family = IPv6;
 		if ( inet_pton(AF_INET6, s.c_str(), val.in.in6.s6_addr) <=0 )
 			{
-			thread->Error(thread->Fmt("Bad address: %s", s.c_str()));
+			thread->Warning(thread->Fmt("Bad address: %s", s.c_str()));
 			memset(val.in.in6.s6_addr, 0, sizeof(val.in.in6.s6_addr));
 			}
 		}

src/threading/formatters/Ascii.cc

@@ -199,7 +199,7 @@ bool Ascii::Describe(ODesc* desc, threading::Value* val, const string& name) con
 		}
 
 	default:
-		GetThread()->Error(GetThread()->Fmt("Ascii writer unsupported field format %d", val->type));
+		GetThread()->Warning(GetThread()->Fmt("Ascii writer unsupported field format %d", val->type));
 		return false;
 	}
 
@@ -346,7 +346,7 @@ threading::Value* Ascii::ParseValue(const string& s, const string& name, TypeTag
 				}
 			}
 
-		GetThread()->Error(GetThread()->Fmt("String '%s' contained no parseable pattern.", candidate.c_str()));
+		GetThread()->Warning(GetThread()->Fmt("String '%s' contained no parseable pattern.", candidate.c_str()));
 		goto parse_error;
 		}
 

testing/btest/Baseline/scripts.base.frameworks.input.bad_patterns/.stderr

@@ -1,9 +1,9 @@
-error: input.log/Input::READER_ASCII: String '/cat/sss' contained no parseable pattern.
+warning: input.log/Input::READER_ASCII: String '/cat/sss' contained no parseable pattern.
 warning: input.log/Input::READER_ASCII: Could not convert line '2	/cat/sss' of input.log to Val. Ignoring line.
-error: input.log/Input::READER_ASCII: String '/foo|bar' contained no parseable pattern.
+warning: input.log/Input::READER_ASCII: String '/foo|bar' contained no parseable pattern.
 warning: input.log/Input::READER_ASCII: Could not convert line '3	/foo|bar' of input.log to Val. Ignoring line.
-error: input.log/Input::READER_ASCII: String 'this is not a pattern' contained no parseable pattern.
+warning: input.log/Input::READER_ASCII: String 'this is not a pattern' contained no parseable pattern.
 warning: input.log/Input::READER_ASCII: Could not convert line '4	this is not a pattern' of input.log to Val. Ignoring line.
-error: input.log/Input::READER_ASCII: String '/5' contained no parseable pattern.
+warning: input.log/Input::READER_ASCII: String '/5' contained no parseable pattern.
 warning: input.log/Input::READER_ASCII: Could not convert line '5	/5' of input.log to Val. Ignoring line.
 received termination signal

testing/btest/Baseline/scripts.base.frameworks.input.invalid-lines/.stderrwithoutfirstline

@@ -0,0 +1,9 @@
+warning: ../input.log/Input::READER_ASCII: Not enough fields in line 'T	-41	SSH::LOG	21	123	tcp	10.0.0.0/24	1.2.3.4	3.14	1315801931.273616	100.000000	hurz	2,4,1,3	CC,AA,BB	EMPTY	10,20,30' of ../input.log. Found 15 fields, want positions 17 and -1
+warning: ../input.log/Input::READER_ASCII: Tried to parse invalid/unknown protocol: whatever
+warning: ../input.log/Input::READER_ASCII: Bad address: 342.2.3.4
+warning: ../input.log/Input::READER_ASCII: Not enough fields in line 'T	-41' of ../input.log. Found 1 fields, want positions 2 and -1
+error: ../input.log/Input::READER_ASCII: Not enough fields in line 'T	-41	SSH::LOG	21	123	tcp	10.0.0.0/24	1.2.3.4	3.14	1315801931.273616	100.000000	hurz	2,4,1,3	CC,AA,BB	EMPTY	10,20,30' of ../input.log. Found 15 fields, want positions 17 and -1
+error: ../input.log/Input::READER_ASCII: Init failed
+error: ../input.log/Input::READER_ASCII: terminating thread
+received termination signal
+>>>

testing/btest/Baseline/scripts.base.frameworks.input.invalid-lines/out

@@ -1,4 +1,16 @@
 {
+[-44] = [b=T, e=SSH::LOG, c=21, p=123/udp, sn=10.0.0.0/24, a=0.0.0.0, d=3.14, t=1315801931.273616, iv=100.0, s=hurz, ns=4242 HOHOHO, sc={
+2,
+4,
+1,
+3
+}, ss={
+BB,
+AA,
+CC
+}, se={
+
+}, vc=[10, 20, 30], ve=[]],
 [-43] = [b=T, e=SSH::LOG, c=21, p=123/unknown, sn=10.0.0.0/24, a=1.2.3.4, d=3.14, t=1315801931.273616, iv=100.0, s=hurz, ns=4242 HOHOHO, sc={
 2,
 4,
@@ -11,7 +23,7 @@ CC
 }, se={
 
 }, vc=[10, 20, 30], ve=[]],
-[-42] = [b=T, e=SSH::LOG, c=21, p=123/unknown, sn=10.0.0.0/24, a=1.2.3.4, d=3.14, t=1315801931.273616, iv=100.0, s=hurz, ns=4242, sc={
+[-42] = [b=T, e=SSH::LOG, c=21, p=123/tcp, sn=10.0.0.0/24, a=1.2.3.4, d=3.14, t=1315801931.273616, iv=100.0, s=hurz, ns=4242, sc={
 2,
 4,
 1,

testing/btest/scripts/base/frameworks/input/invalid-lines.zeek

@@ -1,6 +1,8 @@
 # @TEST-EXEC: btest-bg-run zeek zeek -b %INPUT
 # @TEST-EXEC: btest-bg-wait 10
 # @TEST-EXEC: btest-diff out
+# @TEST-EXEC: sed 1d .stderr > .stderrwithoutfirstline
+# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-sort btest-diff .stderrwithoutfirstline
 
 redef exit_only_after_terminate = T;
 redef InputAscii::fail_on_invalid_lines = F;
@@ -8,11 +10,12 @@ redef InputAscii::fail_on_invalid_lines = F;
 @TEST-START-FILE input.log
 #separator \x09
 #path	ssh
-#fields	b	i	e	c	p	sn	a	d	t	iv	s	sc	ss	se	vc	ve	ns
+#fields	b	i	e	c	p	pt	sn	a	d	t	iv	s	sc	ss	se	vc	ve	ns
-#types	bool	int	enum	count	port	subnet	addr	double	time	interval	string	table	table	table	vector	vector	string
+#types	bool	int	enum	count	port	string	subnet	addr	double	time	interval	string	table	table	table	vector	vector	string
-T	-42	SSH::LOG	21	123	10.0.0.0/24	1.2.3.4	3.14	1315801931.273616	100.000000	hurz	2,4,1,3	CC,AA,BB	EMPTY	10,20,30
+T	-41	SSH::LOG	21	123	tcp	10.0.0.0/24	1.2.3.4	3.14	1315801931.273616	100.000000	hurz	2,4,1,3	CC,AA,BB	EMPTY	10,20,30
-T	-42	SSH::LOG	21	123	10.0.0.0/24	1.2.3.4	3.14	1315801931.273616	100.000000	hurz	2,4,1,3	CC,AA,BB	EMPTY	10,20,30	EMPTY	4242
+T	-42	SSH::LOG	21	123	tcp	10.0.0.0/24	1.2.3.4	3.14	1315801931.273616	100.000000	hurz	2,4,1,3	CC,AA,BB	EMPTY	10,20,30	EMPTY	4242
-T	-43	SSH::LOG	21	123	10.0.0.0/24	1.2.3.4	3.14	1315801931.273616	100.000000	hurz	2,4,1,3	CC,AA,BB	EMPTY	10,20,30	EMPTY	4242 HOHOHO
+T	-43	SSH::LOG	21	123	whatever	10.0.0.0/24	1.2.3.4	3.14	1315801931.273616	100.000000	hurz	2,4,1,3	CC,AA,BB	EMPTY	10,20,30	EMPTY	4242 HOHOHO
+T	-44	SSH::LOG	21	123	udp	10.0.0.0/24	342.2.3.4	3.14	1315801931.273616	100.000000	hurz	2,4,1,3	CC,AA,BB	EMPTY	10,20,30	EMPTY	4242 HOHOHO
 T	-41
 @TEST-END-FILE
 
@@ -32,7 +35,7 @@ type Val: record {
 	b: bool;
 	e: Log::ID;
 	c: count;
-	p: port;
+	p: port &type_column="pt";
 	sn: subnet;
 	a: addr;
 	d: double;