Skip to content

Commit 7abca7f

Browse files
dmitry-lipetskdmitry-lipetsk
authored
xxx::test_logging is corrected (local, remote) (#205)
- these tests configure logging wrong and create the conflicts with root logger - these tests (local and remote) conflict with each other
1 parent 0ffd5f0 commit 7abca7f

File tree

2 files changed

+184
-105
lines changed

2 files changed

+184
-105
lines changed

‎tests/test_simple.py‎

Lines changed: 91 additions & 51 deletions
Original file line numberDiff line numberDiff line change
@@ -8,8 +8,8 @@
88
import pytest
99
import psutil
1010
import platform
11-
12-
import logging.config
11+
import logging
12+
import uuid
1313

1414
from contextlib import contextmanager
1515
from shutil import rmtree
@@ -718,55 +718,95 @@ def test_poll_query_until(self):
718718
node.poll_query_until('select true')
719719

720720
def test_logging(self):
721-
logfile = tempfile.NamedTemporaryFile('w', delete=True)
722-
723-
log_conf = {
724-
'version': 1,
725-
'handlers': {
726-
'file': {
727-
'class': 'logging.FileHandler',
728-
'filename': logfile.name,
729-
'formatter': 'base_format',
730-
'level': logging.DEBUG,
731-
},
732-
},
733-
'formatters': {
734-
'base_format': {
735-
'format': '%(node)-5s: %(message)s',
736-
},
737-
},
738-
'root': {
739-
'handlers': ('file', ),
740-
'level': 'DEBUG',
741-
},
742-
}
743-
744-
logging.config.dictConfig(log_conf)
745-
746-
with scoped_config(use_python_logging=True):
747-
node_name = 'master'
748-
749-
with get_new_node(name=node_name) as master:
750-
master.init().start()
751-
752-
# execute a dummy query a few times
753-
for i in range(20):
754-
master.execute('select 1')
755-
time.sleep(0.01)
756-
757-
# let logging worker do the job
758-
time.sleep(0.1)
759-
760-
# check that master's port is found
761-
with open(logfile.name, 'r') as log:
762-
lines = log.readlines()
763-
assert (any(node_name in s for s in lines))
764-
765-
# test logger after stop/start/restart
766-
master.stop()
767-
master.start()
768-
master.restart()
769-
assert (master._logger.is_alive())
721+
C_MAX_ATTEMPTS = 50
722+
# This name is used for testgres logging, too.
723+
C_NODE_NAME = "testgres_tests." + __class__.__name__ + "test_logging-master-" + uuid.uuid4().hex
724+
725+
logging.info("Node name is [{0}]".format(C_NODE_NAME))
726+
727+
with tempfile.NamedTemporaryFile('w', delete=True) as logfile:
728+
formatter = logging.Formatter(fmt="%(node)-5s: %(message)s")
729+
handler = logging.FileHandler(filename=logfile.name)
730+
handler.formatter = formatter
731+
logger = logging.getLogger(C_NODE_NAME)
732+
assert logger is not None
733+
assert len(logger.handlers) == 0
734+
735+
try:
736+
# It disables to log on the root level
737+
logger.propagate = False
738+
logger.addHandler(handler)
739+
740+
with scoped_config(use_python_logging=True):
741+
with get_new_node(name=C_NODE_NAME) as master:
742+
logging.info("Master node is initilizing")
743+
master.init()
744+
745+
logging.info("Master node is starting")
746+
master.start()
747+
748+
logging.info("Dummy query is executed a few times")
749+
for _ in range(20):
750+
master.execute('select 1')
751+
time.sleep(0.01)
752+
753+
# let logging worker do the job
754+
time.sleep(0.1)
755+
756+
logging.info("Master node log file is checking")
757+
nAttempt = 0
758+
759+
while True:
760+
assert nAttempt <= C_MAX_ATTEMPTS
761+
if nAttempt == C_MAX_ATTEMPTS:
762+
raise Exception("Test failed!")
763+
764+
# let logging worker do the job
765+
time.sleep(0.1)
766+
767+
nAttempt += 1
768+
769+
logging.info("Attempt {0}".format(nAttempt))
770+
771+
# check that master's port is found
772+
with open(logfile.name, 'r') as log:
773+
lines = log.readlines()
774+
775+
assert lines is not None
776+
assert type(lines) == list # noqa: E721
777+
778+
def LOCAL__test_lines():
779+
for s in lines:
780+
if any(C_NODE_NAME in s for s in lines):
781+
logging.info("OK. We found the node_name in a line \"{0}\"".format(s))
782+
return True
783+
return False
784+
785+
if LOCAL__test_lines():
786+
break
787+
788+
logging.info("Master node log file does not have an expected information.")
789+
continue
790+
791+
# test logger after stop/start/restart
792+
logging.info("Master node is stopping...")
793+
master.stop()
794+
logging.info("Master node is staring again...")
795+
master.start()
796+
logging.info("Master node is restaring...")
797+
master.restart()
798+
assert (master._logger.is_alive())
799+
finally:
800+
# It is a hack code to logging cleanup
801+
logging._acquireLock()
802+
assert logging.Logger.manager is not None
803+
assert C_NODE_NAME in logging.Logger.manager.loggerDict.keys()
804+
logging.Logger.manager.loggerDict.pop(C_NODE_NAME, None)
805+
assert not (C_NODE_NAME in logging.Logger.manager.loggerDict.keys())
806+
assert not (handler in logging._handlers.values())
807+
logging._releaseLock()
808+
# GO HOME!
809+
return
770810

771811
def test_pgbench(self):
772812
__class__.helper__skip_test_if_util_not_exist("pgbench")

‎tests/test_simple_remote.py‎

Lines changed: 93 additions & 54 deletions
Original file line numberDiff line numberDiff line change
@@ -8,8 +8,8 @@
88
import six
99
import pytest
1010
import psutil
11-
12-
import logging.config
11+
import logging
12+
import uuid
1313

1414
from contextlib import contextmanager
1515

@@ -788,56 +788,95 @@ def test_poll_query_until(self):
788788
node.poll_query_until('select true')
789789

790790
def test_logging(self):
791-
# FAIL
792-
logfile = tempfile.NamedTemporaryFile('w', delete=True)
793-
794-
log_conf = {
795-
'version': 1,
796-
'handlers': {
797-
'file': {
798-
'class': 'logging.FileHandler',
799-
'filename': logfile.name,
800-
'formatter': 'base_format',
801-
'level': logging.DEBUG,
802-
},
803-
},
804-
'formatters': {
805-
'base_format': {
806-
'format': '%(node)-5s: %(message)s',
807-
},
808-
},
809-
'root': {
810-
'handlers': ('file',),
811-
'level': 'DEBUG',
812-
},
813-
}
814-
815-
logging.config.dictConfig(log_conf)
816-
817-
with scoped_config(use_python_logging=True):
818-
node_name = 'master'
819-
820-
with get_remote_node(name=node_name) as master:
821-
master.init().start()
822-
823-
# execute a dummy query a few times
824-
for i in range(20):
825-
master.execute('select 1')
826-
time.sleep(0.01)
827-
828-
# let logging worker do the job
829-
time.sleep(0.1)
830-
831-
# check that master's port is found
832-
with open(logfile.name, 'r') as log:
833-
lines = log.readlines()
834-
assert (any(node_name in s for s in lines))
835-
836-
# test logger after stop/start/restart
837-
master.stop()
838-
master.start()
839-
master.restart()
840-
assert (master._logger.is_alive())
791+
C_MAX_ATTEMPTS = 50
792+
# This name is used for testgres logging, too.
793+
C_NODE_NAME = "testgres_tests." + __class__.__name__ + "test_logging-master-" + uuid.uuid4().hex
794+
795+
logging.info("Node name is [{0}]".format(C_NODE_NAME))
796+
797+
with tempfile.NamedTemporaryFile('w', delete=True) as logfile:
798+
formatter = logging.Formatter(fmt="%(node)-5s: %(message)s")
799+
handler = logging.FileHandler(filename=logfile.name)
800+
handler.formatter = formatter
801+
logger = logging.getLogger(C_NODE_NAME)
802+
assert logger is not None
803+
assert len(logger.handlers) == 0
804+
805+
try:
806+
# It disables to log on the root level
807+
logger.propagate = False
808+
logger.addHandler(handler)
809+
810+
with scoped_config(use_python_logging=True):
811+
with __class__.helper__get_node(name=C_NODE_NAME) as master:
812+
logging.info("Master node is initilizing")
813+
master.init()
814+
815+
logging.info("Master node is starting")
816+
master.start()
817+
818+
logging.info("Dummy query is executed a few times")
819+
for _ in range(20):
820+
master.execute('select 1')
821+
time.sleep(0.01)
822+
823+
# let logging worker do the job
824+
time.sleep(0.1)
825+
826+
logging.info("Master node log file is checking")
827+
nAttempt = 0
828+
829+
while True:
830+
assert nAttempt <= C_MAX_ATTEMPTS
831+
if nAttempt == C_MAX_ATTEMPTS:
832+
raise Exception("Test failed!")
833+
834+
# let logging worker do the job
835+
time.sleep(0.1)
836+
837+
nAttempt += 1
838+
839+
logging.info("Attempt {0}".format(nAttempt))
840+
841+
# check that master's port is found
842+
with open(logfile.name, 'r') as log:
843+
lines = log.readlines()
844+
845+
assert lines is not None
846+
assert type(lines) == list # noqa: E721
847+
848+
def LOCAL__test_lines():
849+
for s in lines:
850+
if any(C_NODE_NAME in s for s in lines):
851+
logging.info("OK. We found the node_name in a line \"{0}\"".format(s))
852+
return True
853+
return False
854+
855+
if LOCAL__test_lines():
856+
break
857+
858+
logging.info("Master node log file does not have an expected information.")
859+
continue
860+
861+
# test logger after stop/start/restart
862+
logging.info("Master node is stopping...")
863+
master.stop()
864+
logging.info("Master node is staring again...")
865+
master.start()
866+
logging.info("Master node is restaring...")
867+
master.restart()
868+
assert (master._logger.is_alive())
869+
finally:
870+
# It is a hack code to logging cleanup
871+
logging._acquireLock()
872+
assert logging.Logger.manager is not None
873+
assert C_NODE_NAME in logging.Logger.manager.loggerDict.keys()
874+
logging.Logger.manager.loggerDict.pop(C_NODE_NAME, None)
875+
assert not (C_NODE_NAME in logging.Logger.manager.loggerDict.keys())
876+
assert not (handler in logging._handlers.values())
877+
logging._releaseLock()
878+
# GO HOME!
879+
return
841880

842881
def test_pgbench(self):
843882
__class__.helper__skip_test_if_util_not_exist("pgbench")
@@ -1184,9 +1223,9 @@ def test_child_process_dies(self):
11841223
break
11851224

11861225
@staticmethod
1187-
def helper__get_node():
1226+
def helper__get_node(name=None):
11881227
assert __class__.sm_conn_params is not None
1189-
return get_remote_node(conn_params=__class__.sm_conn_params)
1228+
return get_remote_node(name=name, conn_params=__class__.sm_conn_params)
11901229

11911230
@staticmethod
11921231
def helper__restore_envvar(name, prev_value):

0 commit comments

Comments
 (0)