Merge pull request #47088 from adk3798/cephadm-logging

cephadm: reduce spam to cephadm.log

Reviewed-by: John Mulligan <jmulligan@redhat.com>
This commit is contained in:
Adam King 2022-07-27 19:47:16 -04:00 committed by GitHub
commit 257d259e28
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23

View File

@ -86,6 +86,7 @@ CUSTOM_PS1 = r'[ceph: \u@\h \W]\$ '
DEFAULT_TIMEOUT = None # in seconds
DEFAULT_RETRY = 15
DATEFMT = '%Y-%m-%dT%H:%M:%S.%fZ'
QUIET_LOG_LEVEL = 9 # DEBUG is 10, so using 9 to be lower level than DEBUG
logger: logging.Logger = None # type: ignore
@ -238,7 +239,7 @@ class Podman(ContainerEngine):
return self._version
def get_version(self, ctx: CephadmContext) -> None:
out, _, _ = call_throws(ctx, [self.path, 'version', '--format', '{{.Client.Version}}'])
out, _, _ = call_throws(ctx, [self.path, 'version', '--format', '{{.Client.Version}}'], verbosity=CallVerbosity.QUIET)
self._version = _parse_podman_version(out)
def __str__(self) -> str:
@ -619,14 +620,14 @@ class Monitoring(object):
_, err, code = call(ctx, [
ctx.container_engine.path, 'exec', container_id, cmd,
'--version'
], verbosity=CallVerbosity.DEBUG)
], verbosity=CallVerbosity.QUIET)
if code == 0:
break
cmd = 'alertmanager' # reset cmd for version extraction
else:
_, err, code = call(ctx, [
ctx.container_engine.path, 'exec', container_id, cmd, '--version'
], verbosity=CallVerbosity.DEBUG)
], verbosity=CallVerbosity.QUIET)
if code == 0 and \
err.startswith('%s, version ' % cmd):
version = err.split(' ')[2]
@ -717,7 +718,7 @@ class NFSGanesha(object):
out, err, code = call(ctx,
[ctx.container_engine.path, 'exec', container_id,
NFSGanesha.entrypoint, '-v'],
verbosity=CallVerbosity.DEBUG)
verbosity=CallVerbosity.QUIET)
if code == 0:
match = re.search(r'NFS-Ganesha Release\s*=\s*[V]*([\d.]+)', out)
if match:
@ -849,7 +850,7 @@ class CephIscsi(object):
out, err, code = call(ctx,
[ctx.container_engine.path, 'exec', container_id,
'/usr/bin/python3', '-c', "import pkg_resources; print(pkg_resources.require('ceph_iscsi')[0].version)"],
verbosity=CallVerbosity.DEBUG)
verbosity=CallVerbosity.QUIET)
if code == 0:
version = out.strip()
return version
@ -1483,20 +1484,21 @@ class FileLock(object):
try:
while True:
if not self.is_locked:
logger.debug('Acquiring lock %s on %s', lock_id,
lock_filename)
logger.log(QUIET_LOG_LEVEL, 'Acquiring lock %s on %s', lock_id,
lock_filename)
self._acquire()
if self.is_locked:
logger.debug('Lock %s acquired on %s', lock_id,
lock_filename)
logger.log(QUIET_LOG_LEVEL, 'Lock %s acquired on %s', lock_id,
lock_filename)
break
elif timeout >= 0 and time.time() - start_time > timeout:
logger.warning('Timeout acquiring lock %s on %s', lock_id,
lock_filename)
raise Timeout(self._lock_file)
else:
logger.debug(
logger.log(
QUIET_LOG_LEVEL,
'Lock %s not acquired on %s, waiting %s seconds ...',
lock_id, lock_filename, poll_intervall
)
@ -1575,14 +1577,47 @@ class FileLock(object):
# Popen wrappers, lifted from ceph-volume
class CallVerbosity(Enum):
#####
# Format:
# Normal Operation: <log-level-when-no-errors>, Errors: <log-level-when-error>
#
# NOTE: QUIET log level is custom level only used when --verbose is passed
#####
# Normal Operation: None, Errors: None
SILENT = 0
# log stdout/stderr to logger.debug
DEBUG = 1
# On a non-zero exit status, it will forcefully set
# logging ON for the terminal
VERBOSE_ON_FAILURE = 2
# log at info (instead of debug) level.
VERBOSE = 3
# Normal Operation: QUIET, Error: QUIET
QUIET = 1
# Normal Operation: DEBUG, Error: DEBUG
DEBUG = 2
# Normal Operation: QUIET, Error: INFO
QUIET_UNLESS_ERROR = 3
# Normal Operation: DEBUG, Error: INFO
VERBOSE_ON_FAILURE = 4
# Normal Operation: INFO, Error: INFO
VERBOSE = 5
def success_log_level(self) -> int:
_verbosity_level_to_log_level = {
self.SILENT: 0,
self.QUIET: QUIET_LOG_LEVEL,
self.DEBUG: logging.DEBUG,
self.QUIET_UNLESS_ERROR: QUIET_LOG_LEVEL,
self.VERBOSE_ON_FAILURE: logging.DEBUG,
self.VERBOSE: logging.INFO
}
return _verbosity_level_to_log_level[self] # type: ignore
def error_log_level(self) -> int:
_verbosity_level_to_log_level = {
self.SILENT: 0,
self.QUIET: QUIET_LOG_LEVEL,
self.DEBUG: logging.DEBUG,
self.QUIET_UNLESS_ERROR: logging.INFO,
self.VERBOSE_ON_FAILURE: logging.INFO,
self.VERBOSE: logging.INFO
}
return _verbosity_level_to_log_level[self] # type: ignore
if sys.version_info < (3, 8):
@ -1730,10 +1765,6 @@ def call(ctx: CephadmContext,
async for line in reader:
message = line.decode('utf-8')
collected.write(message)
if verbosity == CallVerbosity.VERBOSE:
logger.info(prefix + message.rstrip())
elif verbosity != CallVerbosity.SILENT:
logger.debug(prefix + message.rstrip())
return collected.getvalue()
async def run_with_timeout() -> Tuple[str, str, int]:
@ -1755,13 +1786,14 @@ def call(ctx: CephadmContext,
return stdout, stderr, returncode
stdout, stderr, returncode = async_run(run_with_timeout())
if returncode != 0 and verbosity == CallVerbosity.VERBOSE_ON_FAILURE:
logger.info('Non-zero exit code %d from %s',
returncode, ' '.join(command))
for line in stdout.splitlines():
logger.info(prefix + 'stdout ' + line)
for line in stderr.splitlines():
logger.info(prefix + 'stderr ' + line)
log_level = verbosity.success_log_level()
if returncode != 0:
log_level = verbosity.error_log_level()
logger.log(log_level, f'Non-zero exit code {returncode} from {" ".join(command)}')
for line in stdout.splitlines():
logger.log(log_level, prefix + 'stdout ' + line)
for line in stderr.splitlines():
logger.log(log_level, prefix + 'stderr ' + line)
return stdout, stderr, returncode
@ -2438,7 +2470,7 @@ def check_unit(ctx, unit_name):
installed = False
try:
out, err, code = call(ctx, ['systemctl', 'is-enabled', unit_name],
verbosity=CallVerbosity.DEBUG)
verbosity=CallVerbosity.QUIET)
if code == 0:
enabled = True
installed = True
@ -2452,7 +2484,7 @@ def check_unit(ctx, unit_name):
state = 'unknown'
try:
out, err, code = call(ctx, ['systemctl', 'is-active', unit_name],
verbosity=CallVerbosity.DEBUG)
verbosity=CallVerbosity.QUIET)
out = out.strip()
if out in ['active']:
state = 'running'
@ -3115,7 +3147,7 @@ def extract_uid_gid(ctx, img='', file_path='/var/lib/ceph'):
image=img,
entrypoint='stat',
args=['-c', '%u %g', fp]
).run()
).run(verbosity=CallVerbosity.QUIET_UNLESS_ERROR)
uid, gid = out.split(' ')
return int(uid), int(gid)
except RuntimeError as e:
@ -4040,10 +4072,10 @@ class CephContainer:
]
return ret
def run(self, timeout=DEFAULT_TIMEOUT):
# type: (Optional[int]) -> str
def run(self, timeout=DEFAULT_TIMEOUT, verbosity=CallVerbosity.VERBOSE_ON_FAILURE):
# type: (Optional[int], CallVerbosity) -> str
out, _, _ = call_throws(self.ctx, self.run_cmd(),
desc=self.entrypoint, timeout=timeout)
desc=self.entrypoint, timeout=timeout, verbosity=verbosity)
return out
@ -4590,7 +4622,7 @@ def _pull_image(ctx, image, insecure=False):
cmd_str = ' '.join(cmd)
for sleep_secs in [1, 4, 25]:
out, err, ret = call(ctx, cmd)
out, err, ret = call(ctx, cmd, verbosity=CallVerbosity.QUIET_UNLESS_ERROR)
if not ret:
return
@ -5073,7 +5105,8 @@ def wait_for_mon(
timeout = ctx.timeout if ctx.timeout else 60 # seconds
out, err, ret = call(ctx, c.run_cmd(),
desc=c.entrypoint,
timeout=timeout)
timeout=timeout,
verbosity=CallVerbosity.QUIET_UNLESS_ERROR)
return ret == 0
is_available(ctx, 'mon', is_mon_available)
@ -5100,7 +5133,9 @@ def create_mgr(
# type: () -> bool
timeout = ctx.timeout if ctx.timeout else 60 # seconds
try:
out = clifunc(['status', '-f', 'json-pretty'], timeout=timeout)
out = clifunc(['status', '-f', 'json-pretty'],
timeout=timeout,
verbosity=CallVerbosity.QUIET_UNLESS_ERROR)
j = json.loads(out)
return j.get('mgrmap', {}).get('available', False)
except Exception as e:
@ -5543,8 +5578,8 @@ def command_bootstrap(ctx):
tmp_config = write_tmp(config, uid, gid)
# a CLI helper to reduce our typing
def cli(cmd, extra_mounts={}, timeout=DEFAULT_TIMEOUT):
# type: (List[str], Dict[str, str], Optional[int]) -> str
def cli(cmd, extra_mounts={}, timeout=DEFAULT_TIMEOUT, verbosity=CallVerbosity.VERBOSE_ON_FAILURE):
# type: (List[str], Dict[str, str], Optional[int], CallVerbosity) -> str
mounts = {
log_dir: '/var/log/ceph:z',
admin_keyring.name: '/etc/ceph/ceph.client.admin.keyring:z',
@ -5559,7 +5594,7 @@ def command_bootstrap(ctx):
entrypoint='/usr/bin/ceph',
args=cmd,
volume_mounts=mounts,
).run(timeout=timeout)
).run(timeout=timeout, verbosity=verbosity)
wait_for_mon(ctx, mon_id, mon_dir, admin_keyring.name, tmp_config.name)
@ -5596,9 +5631,9 @@ def command_bootstrap(ctx):
# stat' command first, then fall back to 'mgr dump' if
# necessary
try:
j = json_loads_retry(lambda: cli(['mgr', 'stat']))
j = json_loads_retry(lambda: cli(['mgr', 'stat'], verbosity=CallVerbosity.QUIET_UNLESS_ERROR))
except Exception:
j = json_loads_retry(lambda: cli(['mgr', 'dump']))
j = json_loads_retry(lambda: cli(['mgr', 'dump'], verbosity=CallVerbosity.QUIET_UNLESS_ERROR))
epoch = j['epoch']
# wait for mgr to have it
@ -6090,7 +6125,7 @@ def command_ceph_volume(ctx):
volume_mounts=mounts,
)
out, err, code = call_throws(ctx, c.run_cmd())
out, err, code = call_throws(ctx, c.run_cmd(), verbosity=CallVerbosity.QUIET_UNLESS_ERROR)
if not code:
print(out)
@ -6155,7 +6190,7 @@ def _list_ipv4_networks(ctx: CephadmContext) -> Dict[str, Dict[str, Set[str]]]:
execstr: Optional[str] = find_executable('ip')
if not execstr:
raise FileNotFoundError("unable to find 'ip' command")
out, _, _ = call_throws(ctx, [execstr, 'route', 'ls'])
out, _, _ = call_throws(ctx, [execstr, 'route', 'ls'], verbosity=CallVerbosity.QUIET_UNLESS_ERROR)
return _parse_ipv4_route(out)
@ -6183,8 +6218,8 @@ def _list_ipv6_networks(ctx: CephadmContext) -> Dict[str, Dict[str, Set[str]]]:
execstr: Optional[str] = find_executable('ip')
if not execstr:
raise FileNotFoundError("unable to find 'ip' command")
routes, _, _ = call_throws(ctx, [execstr, '-6', 'route', 'ls'])
ips, _, _ = call_throws(ctx, [execstr, '-6', 'addr', 'ls'])
routes, _, _ = call_throws(ctx, [execstr, '-6', 'route', 'ls'], verbosity=CallVerbosity.QUIET_UNLESS_ERROR)
ips, _, _ = call_throws(ctx, [execstr, '-6', 'addr', 'ls'], verbosity=CallVerbosity.QUIET_UNLESS_ERROR)
return _parse_ipv6_route(routes, ips)
@ -6290,14 +6325,14 @@ def list_daemons(ctx, detail=True, legacy_dir=None):
out, err, code = call(
ctx,
[container_path, 'stats', '--format', '{{.ID}},{{.MemUsage}}', '--no-stream'],
verbosity=CallVerbosity.DEBUG
verbosity=CallVerbosity.QUIET
)
seen_memusage_cid_len, seen_memusage = _parse_mem_usage(code, out)
out, err, code = call(
ctx,
[container_path, 'stats', '--format', '{{.ID}},{{.CPUPerc}}', '--no-stream'],
verbosity=CallVerbosity.DEBUG
verbosity=CallVerbosity.QUIET
)
seen_cpuperc_cid_len, seen_cpuperc = _parse_cpu_perc(code, out)
@ -6326,7 +6361,7 @@ def list_daemons(ctx, detail=True, legacy_dir=None):
try:
out, err, code = call(ctx,
['ceph', '-v'],
verbosity=CallVerbosity.DEBUG)
verbosity=CallVerbosity.QUIET)
if not code and out.startswith('ceph version '):
host_version = out.split(' ')[2]
except Exception:
@ -6377,7 +6412,7 @@ def list_daemons(ctx, detail=True, legacy_dir=None):
container_path, 'image', 'inspect', image_id,
'--format', '{{.RepoDigests}}',
],
verbosity=CallVerbosity.DEBUG)
verbosity=CallVerbosity.QUIET)
if not code:
image_digests = list(set(map(
normalize_image_digest,
@ -6396,7 +6431,7 @@ def list_daemons(ctx, detail=True, legacy_dir=None):
out, err, code = call(ctx,
[container_path, 'exec', container_id,
'ceph', '-v'],
verbosity=CallVerbosity.DEBUG)
verbosity=CallVerbosity.QUIET)
if not code and \
out.startswith('ceph version '):
version = out.split(' ')[2]
@ -6405,7 +6440,7 @@ def list_daemons(ctx, detail=True, legacy_dir=None):
out, err, code = call(ctx,
[container_path, 'exec', container_id,
'grafana-server', '-v'],
verbosity=CallVerbosity.DEBUG)
verbosity=CallVerbosity.QUIET)
if not code and \
out.startswith('Version '):
version = out.split(' ')[1]
@ -6421,7 +6456,7 @@ def list_daemons(ctx, detail=True, legacy_dir=None):
out, err, code = call(ctx,
[container_path, 'exec', container_id,
'haproxy', '-v'],
verbosity=CallVerbosity.DEBUG)
verbosity=CallVerbosity.QUIET)
if not code and \
out.startswith('HA-Proxy version '):
version = out.split(' ')[2]
@ -6430,7 +6465,7 @@ def list_daemons(ctx, detail=True, legacy_dir=None):
out, err, code = call(ctx,
[container_path, 'exec', container_id,
'keepalived', '--version'],
verbosity=CallVerbosity.DEBUG)
verbosity=CallVerbosity.QUIET)
if not code and \
err.startswith('Keepalived '):
version = err.split(' ')[1]
@ -6540,7 +6575,7 @@ def get_container_stats(ctx: CephadmContext, container_path: str, fsid: str, dae
'--format', '{{.Id}},{{.Config.Image}},{{.Image}},{{.Created}},{{index .Config.Labels "io.ceph.version"}}',
name
]
out, err, code = call(ctx, cmd, verbosity=CallVerbosity.DEBUG)
out, err, code = call(ctx, cmd, verbosity=CallVerbosity.QUIET)
if not code:
break
return out, err, code
@ -8632,7 +8667,7 @@ class HostFacts():
security = {}
try:
out, err, code = call(self.ctx, ['sestatus'],
verbosity=CallVerbosity.DEBUG)
verbosity=CallVerbosity.QUIET)
security['type'] = 'SELinux'
status, mode, policy = '', '', ''
for line in out.split('\n'):
@ -9542,6 +9577,7 @@ def cephadm_init_logging(ctx: CephadmContext, args: List[str]) -> None:
"""Configure the logging for cephadm as well as updating the system
to have the expected log dir and logrotate configuration.
"""
logging.addLevelName(QUIET_LOG_LEVEL, 'QUIET')
global logger
if not os.path.exists(LOG_DIR):
os.makedirs(LOG_DIR)
@ -9552,6 +9588,7 @@ def cephadm_init_logging(ctx: CephadmContext, args: List[str]) -> None:
dictConfig(logging_config)
logger = logging.getLogger()
logger.setLevel(QUIET_LOG_LEVEL)
if not os.path.exists(ctx.logrotate_dir + '/cephadm'):
with open(ctx.logrotate_dir + '/cephadm', 'w') as f:
@ -9568,8 +9605,8 @@ def cephadm_init_logging(ctx: CephadmContext, args: List[str]) -> None:
if ctx.verbose:
for handler in logger.handlers:
if handler.name == 'console':
handler.setLevel(logging.DEBUG)
if handler.name in ['console', 'log_file', 'console_stdout']:
handler.setLevel(QUIET_LOG_LEVEL)
logger.debug('%s\ncephadm %s' % ('-' * 80, args))