Merge branch '0.10' into 0.11

ChangeLog

@@ -64,6 +64,13 @@ ver. 0.10.4-dev-1 (20??/??/??) - development edition
 * `filter.d/dovecot.conf`: failregex enhancement to catch sql password mismatch errors (gh-2153);
 * `action.d/hostsdeny.conf`: fix parameter in config (dynamic parameters stating with '_' are protected 
   and don't allowed in command-actions), see gh-2114;
+* decoding stability fix by wrong encoded characters like utf-8 surrogate pairs, etc (gh-2171):
+  - fail2ban running in the preferred encoding now (as default encoding also within python 2.x), mostly
+    `UTF-8` in opposite to `ascii` previously, so minimizes influence of implicit conversions errors;
+  - actions: avoid possible conversion errors on wrong-chars by replace tags;
+  - database: improve adapter/converter handlers working on invalid characters in sense of json and/or sqlite-database;
+    additionally both are exception-safe now, so avoid possible locking of database (closes gh-2137);
+  - logging in fail2ban is process-wide exception-safe now.
 
 ### New Features
 

config/action.d/badips.py

@@ -18,16 +18,16 @@
 # Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA  02110-1301, USA.
 
 import sys
-if sys.version_info < (2, 7):
+if sys.version_info < (2, 7): # pragma: no cover
 	raise ImportError("badips.py action requires Python >= 2.7")
 import json
 import threading
 import logging
-if sys.version_info >= (3, ):
+if sys.version_info >= (3, ): # pragma: 2.x no cover
 	from urllib.request import Request, urlopen
 	from urllib.parse import urlencode
 	from urllib.error import HTTPError
-else:
+else: # pragma: 3.x no cover
 	from urllib2 import Request, urlopen, HTTPError
 	from urllib import urlencode
 

fail2ban/helpers.py

@@ -45,7 +45,7 @@ if PREFER_ENC.startswith('ANSI_'): # pragma: no cover
 # caused by implicit converting of string/unicode (e. g. `str(u"\uFFFD")` produces an error
 # if default encoding is 'ascii');
 if sys.version_info < (3,): # pragma: 3.x no cover
-  # correct default (global system) encoding (mostly UTF-8):
+	# correct default (global system) encoding (mostly UTF-8):
 	def __resetDefaultEncoding(encoding):
 		global PREFER_ENC
 		ode = sys.getdefaultencoding().upper()
@@ -202,6 +202,35 @@ class FormatterWithTraceBack(logging.Formatter):
 		return logging.Formatter.format(self, record)
 
 
+__origLog = logging.Logger._log
+def __safeLog(self, level, msg, args, **kwargs):
+	"""Safe log inject to avoid possible errors by unsafe log-handlers, 
+	concat, str. conversion, representation fails, etc.
+
+	Used to intrude exception-safe _log-method instead of _log-method 
+	of Logger class to be always safe by logging and to get more-info about.
+
+	See testSafeLogging test-case for more information. At least the errors
+	covered in phase 3 seems to affected in all known pypy/python versions 
+	until now.
+	"""
+	try:
+		# if isEnabledFor(level) already called...
+		__origLog(self, level, msg, args, **kwargs)
+	except Exception as e: # pragma: no cover - unreachable if log-handler safe in this python-version
+		try:
+			for args in (
+				("logging failed: %r on %s", (e, uni_string(msg))),
+				("  args: %r", ([uni_string(a) for a in args],))
+			):
+				try:
+					__origLog(self, level, *args)
+				except: # pragma: no cover
+					pass
+		except: # pragma: no cover
+			pass
+logging.Logger._log = __safeLog
+
 def getLogger(name):
 	"""Get logging.Logger instance with Fail2Ban logger name convention
 	"""

fail2ban/server/database.py

@@ -40,7 +40,7 @@ logSys = getLogger(__name__)
 
 
 def _json_default(x):
-	"""Avoid errors on types unknow in json-adapters."""
+	"""Avoid errors on types unknown in json-adapters."""
 	if isinstance(x, set):
 		x = list(x)
 	return uni_string(x)
@@ -51,11 +51,8 @@ if sys.version_info >= (3,): # pragma: 2.x no cover
 			x = json.dumps(x, ensure_ascii=False, default=_json_default).encode(
 				PREFER_ENC, 'replace')
 		except Exception as e:
-			# adapter handler should be exception-safe, so avoid possible errors in log-handlers (concat, str. conversion, etc)
-			try:
-				logSys.error('json dumps failed: %r', e, exc_info=logSys.getEffectiveLevel() <= 4)
-			except: # pragma: no cover
-				pass
+			# adapter handler should be exception-safe
+			logSys.error('json dumps failed: %r', e, exc_info=logSys.getEffectiveLevel() <= 4)
 			x = '{}'
 		return x
 
@@ -63,11 +60,8 @@ if sys.version_info >= (3,): # pragma: 2.x no cover
 		try:
 			x = json.loads(x.decode(PREFER_ENC, 'replace'))
 		except Exception as e:
-			# converter handler should be exception-safe, so avoid possible errors in log-handlers (concat, str. conversion, etc)
-			try:
-				logSys.error('json loads failed: %r', e, exc_info=logSys.getEffectiveLevel() <= 4)
-			except: # pragma: no cover
-				pass
+			# converter handler should be exception-safe
+			logSys.error('json loads failed: %r', e, exc_info=logSys.getEffectiveLevel() <= 4)
 			x = {}
 		return x
 else: # pragma: 3.x no cover
@@ -87,11 +81,8 @@ else: # pragma: 3.x no cover
 		try:
 			x = json.dumps(_normalize(x), ensure_ascii=False, default=_json_default)
 		except Exception as e:
-			# adapter handler should be exception-safe, so avoid possible errors in log-handlers (concat, str. conversion, etc)
-			try:
-				logSys.error('json dumps failed: %r', e, exc_info=logSys.getEffectiveLevel() <= 4)
-			except: # pragma: no cover
-				pass
+			# adapter handler should be exception-safe
+			logSys.error('json dumps failed: %r', e, exc_info=logSys.getEffectiveLevel() <= 4)
 			x = '{}'
 		return x
 
@@ -99,11 +90,8 @@ else: # pragma: 3.x no cover
 		try:
 			x = json.loads(x.decode(PREFER_ENC, 'replace'))
 		except Exception as e:
-			# converter handler should be exception-safe, so avoid possible errors in log-handlers (concat, str. conversion, etc)
-			try:
-				logSys.error('json loads failed: %r', e, exc_info=logSys.getEffectiveLevel() <= 4)
-			except: # pragma: no cover
-				pass
+			# converter handler should be exception-safe
+			logSys.error('json loads failed: %r', e, exc_info=logSys.getEffectiveLevel() <= 4)
 			x = {}
 		return x
 

fail2ban/tests/action_d/test_badips.py

@@ -29,9 +29,9 @@ from ..dummyjail import DummyJail
 from ..servertestcase import IPAddr
 from ..utils import LogCaptureTestCase, CONFIG_DIR
 
-if sys.version_info >= (3, ):
+if sys.version_info >= (3, ): # pragma: 2.x no cover
 	from urllib.error import HTTPError, URLError
-else:
+else: # pragma: 3.x no cover
 	from urllib2 import HTTPError, URLError
 
 def skip_if_not_available(f):

fail2ban/tests/databasetestcase.py

@@ -305,6 +305,7 @@ class DatabaseTest(LogCaptureTestCase):
 			self.assertEqual(readtickets[i].getIP(), ticket.getIP())
 			self.assertEqual(len(readtickets[i].getMatches()), len(ticket.getMatches()))
 
+		self.pruneLog('[test-phase 2] simulate errors')
 		## simulate errors in dumps/loads:
 		priorEnc = database.PREFER_ENC
 		try:
@@ -323,6 +324,13 @@ class DatabaseTest(LogCaptureTestCase):
 			self.assertEqual(len(readtickets), 14)
 		finally:
 			database.PREFER_ENC = priorEnc
+		
+		## check the database is still operable (not locked) after all the errors:
+		self.pruneLog('[test-phase 3] still operable?')
+		self.db.addBan(self.jail, FailTicket("127.0.0.8"))
+		readtickets = self.db.getBans(jail=self.jail)
+		self.assertEqual(len(readtickets), 15)
+		self.assertNotLogged("json loads failed", "json dumps failed")
 
 	def _testAdd3Bans(self):
 		self.testAddJail()

fail2ban/tests/misctestcase.py

@@ -201,6 +201,48 @@ class TestsUtilsTest(LogCaptureTestCase):
 		uni_string('test\xcf')
 		uni_string(u'test\xcf')
 
+	def testSafeLogging(self):
+		# logging should be exception-safe, to avoid possible errors (concat, str. conversion, representation failures, etc)
+		logSys = DefLogSys
+		class Test:
+			def __init__(self, err=1):
+				self.err = err
+			def __repr__(self):
+				if self.err:
+					raise Exception('no represenation for test!')
+				else:
+					return u'conv-error (\xf2\xf0\xe5\xf2\xe8\xe9), unterminated utf \xcf'
+		test = Test()
+		logSys.log(logging.NOTICE, "test 1a: %r", test)
+		self.assertLogged("Traceback", "no represenation for test!")
+		self.pruneLog()
+		logSys.notice("test 1b: %r", test)
+		self.assertLogged("Traceback", "no represenation for test!")
+
+		self.pruneLog('[phase 2] test error conversion by encoding %s' % sys.getdefaultencoding())
+		test = Test(0)
+		# this may produce coversion error on ascii default encoding:
+		#str(test)
+		logSys.log(logging.NOTICE, "test 2a: %r, %s", test, test)
+		self.assertLogged("test 2a", "Error by logging handler", all=False)
+		logSys.notice("test 2b: %r, %s", test, test)
+		self.assertLogged("test 2b", "Error by logging handler", all=False)
+
+		self.pruneLog('[phase 3] test unexpected error in handler')
+		class _ErrorHandler(logging.Handler):
+			def handle(self, record):
+				raise Exception('error in handler test!')
+		_org_handler = logSys.handlers
+		try:
+			logSys.handlers = list(logSys.handlers)
+			logSys.handlers += [_ErrorHandler()]
+			logSys.log(logging.NOTICE, "test 3a")
+			logSys.notice("test 3b")
+		finally:
+			logSys.handlers = _org_handler
+		# we should reach this line without errors!
+		self.pruneLog('OK')
+
 	def testTraceBack(self):
 		# pretty much just a smoke test since tests runners swallow all the detail
 
@@ -374,13 +416,10 @@ class TestsUtilsTest(LogCaptureTestCase):
 
 	def testLazyLogging(self):
 		logSys = DefLogSys
-		if unittest.F2B.log_lazy:
-			# wrong logging syntax will throw an error lazy (on demand):
-			logSys.debug('test', 1, 2, 3)
-			self.assertRaisesRegexp(Exception, 'not all arguments converted', lambda: self.assertNotLogged('test'))
-		else: # pragma: no cover
-			# wrong logging syntax will throw an error directly:
-			self.assertRaisesRegexp(Exception, 'not all arguments converted', lambda: logSys.debug('test', 1, 2, 3))
+		logSys.debug('lazy logging: %r', unittest.F2B.log_lazy)
+		# wrong logging syntax will don't throw an error anymore (logged now):
+		logSys.notice('test', 1, 2, 3)
+		self.assertLogged('not all arguments converted')
 
 
 class MyTimeTest(unittest.TestCase):

fail2ban/tests/utils.py

@@ -671,11 +671,14 @@ class LogCaptureTestCase(unittest.TestCase):
 				self._strm.truncate(0)
 
 		def __write(self, record):
-			msg = record.getMessage() + '\n'
 			try:
-				self._strm.write(msg)
-			except UnicodeEncodeError: # pragma: no cover - normally unreachable now
-				self._strm.write(msg.encode('UTF-8', 'replace'))
+				msg = record.getMessage() + '\n'
+				try:
+					self._strm.write(msg)
+				except UnicodeEncodeError: # pragma: no cover - normally unreachable now
+					self._strm.write(msg.encode('UTF-8', 'replace'))
+			except Exception as e: # pragma: no cover - normally unreachable
+				self._strm.write('Error by logging handler: %r' % e)
 
 		def getvalue(self):
 			"""Return current buffer as whole string."""