From 6bf0f04ae2cb4e2c33a9836125a41e9e6b21e4d7 Mon Sep 17 00:00:00 2001 From: Alasdair G Kergon Date: Mon, 13 Nov 2017 14:43:32 +0000 Subject: [PATCH] log: Improve various device-related messages - Use 'lvmcache' consistently instead of 'metadata cache' - Always use 5 characters for source line number - Remember to convert uuids into printable form - Use rather than (null) when VG has no name. --- lib/cache/lvmcache.c | 10 +++++----- lib/device/dev-cache.c | 6 +++--- lib/device/dev-ext.c | 14 ++++++-------- lib/device/dev-io.c | 12 +++++------- lib/filters/filter-internal.c | 2 +- lib/filters/filter-persistent.c | 1 + lib/log/log.c | 8 ++++---- lib/metadata/metadata.c | 10 ++++++++-- lib/metadata/vg.c | 4 ++-- tools/lvmcmdline.c | 8 ++++---- tools/toollib.c | 6 +++--- 11 files changed, 42 insertions(+), 39 deletions(-) diff --git a/lib/cache/lvmcache.c b/lib/cache/lvmcache.c index c51e157f0..5d4732c41 100644 --- a/lib/cache/lvmcache.c +++ b/lib/cache/lvmcache.c @@ -154,7 +154,7 @@ static void _free_cached_vgmetadata(struct lvmcache_vginfo *vginfo) vginfo->cft = NULL; } - log_debug_cache("Metadata cache: VG %s wiped.", vginfo->vgname); + log_debug_cache("lvmcache: VG %s wiped.", vginfo->vgname); release_vg(vginfo->cached_vg); } @@ -197,7 +197,7 @@ static void _store_metadata(struct volume_group *vg, unsigned precommitted) return; } - log_debug_cache("Metadata cache: VG %s (%s) stored (%" PRIsize_t " bytes%s).", + log_debug_cache("lvmcache: VG %s (%s) stored (%" PRIsize_t " bytes%s).", vginfo->vgname, uuid, size, precommitted ? ", precommitted" : ""); } @@ -289,7 +289,7 @@ void lvmcache_commit_metadata(const char *vgname) return; if (vginfo->precommitted) { - log_debug_cache("Precommitted metadata cache: VG %s upgraded to committed.", + log_debug_cache("lvmcache: Upgraded pre-committed VG %s metadata to committed.", vginfo->vgname); vginfo->precommitted = 0; } @@ -616,7 +616,7 @@ struct lvmcache_vginfo *lvmcache_vginfo_from_vgid(const char *vgid) id[ID_LEN] = '\0'; if (!(vginfo = dm_hash_lookup(_vgid_hash, id))) { - log_debug_cache("Metadata cache has no info for vgid \"%s\"", id); + log_debug_cache("lvmcache has no info for vgid \"%s\"", id); return NULL; } @@ -1870,7 +1870,7 @@ static int _lvmcache_update_vgname(struct lvmcache_info *info, vginfo->vgid[0] ? vginfo->vgid : "", vginfo->vgid[0] ? ")" : "", mdabuf); } else - log_debug_cache("lvmcache initialised VG %s.", vgname); + log_debug_cache("lvmcache: Initialised VG %s.", vgname); return 1; } diff --git a/lib/device/dev-cache.c b/lib/device/dev-cache.c index dd12da1fb..2cd38f417 100644 --- a/lib/device/dev-cache.c +++ b/lib/device/dev-cache.c @@ -708,7 +708,7 @@ static int _insert_dev(const char *path, dev_t d) if (dm_hash_lookup(_cache.names, path) == dev) { /* Hash already has matching entry present */ - log_debug("Path already cached %s.", path); + log_debug("%s: Path already cached.", path); return 1; } @@ -1423,7 +1423,7 @@ struct device *dev_cache_get(const char *name, struct dev_filter *f) if (!d || (f && !(d->flags & DEV_REGULAR) && !(f->passes_filter(f, d)))) return NULL; - log_debug_devs("Using %s", dev_name(d)); + log_debug_devs("%s: Using device (%d:%d)", dev_name(d), (int) MAJOR(d->dev), (int) MINOR(d->dev)); return d; } @@ -1533,7 +1533,7 @@ struct device *dev_iter_get(struct dev_iter *iter) struct device *d = _iter_next(iter); if (!iter->filter || (d->flags & DEV_REGULAR) || iter->filter->passes_filter(iter->filter, d)) { - log_debug_devs("Using %s", dev_name(d)); + log_debug_devs("%s: Using device (%d:%d)", dev_name(d), (int) MAJOR(d->dev), (int) MINOR(d->dev)); return d; } } diff --git a/lib/device/dev-ext.c b/lib/device/dev-ext.c index 0cc8279ae..0c3b435d5 100644 --- a/lib/device/dev-ext.c +++ b/lib/device/dev-ext.c @@ -100,8 +100,6 @@ const char *dev_ext_name(struct device *dev) return _ext_registry[dev->ext.src].name; } -static const char *_ext_attached_msg = "External handle attached to device"; - struct dev_ext *dev_ext_get(struct device *dev) { struct dev_ext *ext; @@ -110,10 +108,10 @@ struct dev_ext *dev_ext_get(struct device *dev) handle_ptr = dev->ext.handle; if (!(ext = _ext_registry[dev->ext.src].dev_ext_get(dev))) - log_error("Failed to get external handle for device %s [%s].", + log_error("%s: Failed to get external handle [%s].", dev_name(dev), dev_ext_name(dev)); else if (handle_ptr != dev->ext.handle) - log_debug_devs("%s %s [%s:%p]", _ext_attached_msg, dev_name(dev), + log_debug_devs("%s: External handle [%s:%p] attached", dev_name(dev), dev_ext_name(dev), dev->ext.handle); return ext; @@ -131,10 +129,10 @@ int dev_ext_release(struct device *dev) handle_ptr = dev->ext.handle; if (!(r = _ext_registry[dev->ext.src].dev_ext_release(dev))) - log_error("Failed to release external handle for device %s [%s:%p].", + log_error("%s: Failed to release external handle [%s:%p]", dev_name(dev), dev_ext_name(dev), dev->ext.handle); else - log_debug_devs("External handle detached from device %s [%s:%p]", + log_debug_devs("%s: External handle [%s:%p] detached", dev_name(dev), dev_ext_name(dev), handle_ptr); return r; @@ -143,7 +141,7 @@ int dev_ext_release(struct device *dev) int dev_ext_enable(struct device *dev, dev_ext_t src) { if (dev->ext.enabled && (dev->ext.src != src) && !dev_ext_release(dev)) { - log_error("Failed to enable external handle for device %s [%s].", + log_error("%s: Failed to enable external handle [%s].", dev_name(dev), _ext_registry[src].name); return 0; } @@ -160,7 +158,7 @@ int dev_ext_disable(struct device *dev) return 1; if (!dev_ext_release(dev)) { - log_error("Failed to disable external handle for device %s [%s].", + log_error("%s: Failed to disable external handle [%s].", dev_name(dev), dev_ext_name(dev)); return 0; } diff --git a/lib/device/dev-io.c b/lib/device/dev-io.c index 519b5c7e1..328ec30e9 100644 --- a/lib/device/dev-io.c +++ b/lib/device/dev-io.c @@ -142,7 +142,7 @@ int dev_get_block_size(struct device *dev, unsigned int *physical_block_size, un r = 0; goto out; } - log_debug_devs("%s: block size is %u bytes", name, dev->block_size); + log_debug_devs("%s: Block size is %u bytes", name, dev->block_size); } #ifdef BLKPBSZGET @@ -153,7 +153,7 @@ int dev_get_block_size(struct device *dev, unsigned int *physical_block_size, un r = 0; goto out; } - log_debug_devs("%s: physical block size is %u bytes", name, dev->phys_block_size); + log_debug_devs("%s: Physical block size is %u bytes", name, dev->phys_block_size); } #elif defined (BLKSSZGET) /* if we can't get physical block size, just use logical block size instead */ @@ -163,15 +163,13 @@ int dev_get_block_size(struct device *dev, unsigned int *physical_block_size, un r = 0; goto out; } - log_debug_devs("%s: physical block size can't be determined, using logical " - "block size of %u bytes", name, dev->phys_block_size); + log_debug_devs("%s: Physical block size can't be determined: Using logical block size of %u bytes", name, dev->phys_block_size); } #else /* if even BLKSSZGET is not available, use default 512b */ if (dev->phys_block_size == -1) { dev->phys_block_size = 512; - log_debug_devs("%s: physical block size can't be determined, using block " - "size of %u bytes instead", name, dev->phys_block_size); + log_debug_devs("%s: Physical block size can't be determined: Using block size of %u bytes instead", name, dev->phys_block_size); } #endif @@ -464,7 +462,7 @@ int dev_open_flags(struct device *dev, int flags, int direct, int quiet) } if (dev->open_count && !need_excl) { - log_debug_devs("%s already opened read-only. Upgrading " + log_debug_devs("%s: Already opened read-only. Upgrading " "to read-write.", dev_name(dev)); dev->open_count++; } diff --git a/lib/filters/filter-internal.c b/lib/filters/filter-internal.c index 1a58a37b2..cdaee4e73 100644 --- a/lib/filters/filter-internal.c +++ b/lib/filters/filter-internal.c @@ -74,7 +74,7 @@ struct dev_filter *internal_filter_create(void) f->destroy = _destroy; f->use_count = 0; - log_debug_devs("internal filter initialised."); + log_debug_devs("Internal filter initialised."); return f; } diff --git a/lib/filters/filter-persistent.c b/lib/filters/filter-persistent.c index 4e8161e29..5bc0861fd 100644 --- a/lib/filters/filter-persistent.c +++ b/lib/filters/filter-persistent.c @@ -119,6 +119,7 @@ int persistent_filter_load(struct dev_filter *f, struct dm_config_tree **cft_out if (!config_file_read(cft)) goto_out; + log_debug_devs("Loading persistent filter cache from %s", pf->file); _read_array(pf, cft, "persistent_filter_cache/valid_devices", PF_GOOD_DEVICE); /* We don't gain anything by holding invalid devices */ diff --git a/lib/log/log.c b/lib/log/log.c index c0789b456..208959bc3 100644 --- a/lib/log/log.c +++ b/lib/log/log.c @@ -594,7 +594,7 @@ static void _vprint_log(int level, const char *file, int line, int dm_errno_or_c log_it: if (!logged_via_report && ((verbose_level() >= level) && !_log_suppress)) { if (verbose_level() > _LOG_DEBUG) { - (void) dm_snprintf(buf, sizeof(buf), "#%s:%d ", + (void) dm_snprintf(buf, sizeof(buf), "#%s:%-5d ", file, line); } else buf[0] = '\0'; @@ -639,7 +639,7 @@ static void _vprint_log(int level, const char *file, int line, int dm_errno_or_c } if (_log_to_file && (_log_while_suspended || !critical_section())) { - fprintf(_log_file, "%s:%d %s%s", file, line, log_command_name(), + fprintf(_log_file, "%s:%-5d %s%s", file, line, log_command_name(), _msg_prefix); va_copy(ap, orig_ap); @@ -647,7 +647,7 @@ static void _vprint_log(int level, const char *file, int line, int dm_errno_or_c va_end(ap); if (_log_file_max_lines && ++_log_file_lines >= _log_file_max_lines) { - fprintf(_log_file, "\n%s:%d %sAborting. Command has reached limit " + fprintf(_log_file, "\n%s:%-5d %sAborting. Command has reached limit " "for logged lines (LVM_LOG_FILE_MAX_LINES=" FMTu64 ").", file, line, _msg_prefix, _log_file_max_lines); @@ -673,7 +673,7 @@ static void _vprint_log(int level, const char *file, int line, int dm_errno_or_c memset(&buf, ' ', sizeof(buf)); bufused = 0; if ((n = dm_snprintf(buf, sizeof(buf), - "%s:%d %s%s", file, line, log_command_name(), + "%s:%-5d %s%s", file, line, log_command_name(), _msg_prefix)) == -1) goto done; diff --git a/lib/metadata/metadata.c b/lib/metadata/metadata.c index b5acf07a0..d823ef200 100644 --- a/lib/metadata/metadata.c +++ b/lib/metadata/metadata.c @@ -3797,12 +3797,18 @@ static struct volume_group *_vg_read(struct cmd_context *cmd, struct dm_list *pvids; struct pv_list *pvl; struct dm_list all_pvs; + char uuid[64] __attribute__((aligned(8))); + unsigned seqno = 0; int reappeared = 0; struct cached_vg_fmtdata *vg_fmtdata = NULL; /* Additional format-specific data about the vg */ unsigned use_previous_vg; - log_very_verbose("Reading VG %s %.32s", vgname ?: "", vgid ?: ""); + uuid[0] = '\0'; + if (vgid && !id_write_format((const struct id*)vgid, uuid, sizeof(uuid))) + stack; + + log_very_verbose("Reading VG %s %s", vgname ?: "", vgid ? uuid : ""); if (is_orphan_vg(vgname)) { if (use_precommitted) { @@ -3879,7 +3885,7 @@ static struct volume_group *_vg_read(struct cmd_context *cmd, /* Now determine the correct vgname if none was supplied */ if (!vgname && !(vgname = lvmcache_vgname_from_vgid(cmd->mem, vgid))) { - log_debug_metadata("Cache did not find VG name from vgid %.32s", vgid); + log_debug_metadata("Cache did not find VG name from vgid %s", uuid); return_NULL; } diff --git a/lib/metadata/vg.c b/lib/metadata/vg.c index 9f48a9ba7..f90ac821c 100644 --- a/lib/metadata/vg.c +++ b/lib/metadata/vg.c @@ -71,7 +71,7 @@ struct volume_group *alloc_vg(const char *pool_name, struct cmd_context *cmd, dm_list_init(&vg->removed_historical_lvs); dm_list_init(&vg->removed_pvs); - log_debug_mem("Allocated VG %s at %p.", vg->name, vg); + log_debug_mem("Allocated VG %s at %p.", vg->name ? : "", vg); return vg; } @@ -86,7 +86,7 @@ static void _free_vg(struct volume_group *vg) return; } - log_debug_mem("Freeing VG %s at %p.", vg->name, vg); + log_debug_mem("Freeing VG %s at %p.", vg->name ? : "", vg); dm_hash_destroy(vg->hostnames); dm_pool_destroy(vg->vgmem); diff --git a/tools/lvmcmdline.c b/tools/lvmcmdline.c index ed73b8d25..22f1c6003 100644 --- a/tools/lvmcmdline.c +++ b/tools/lvmcmdline.c @@ -1864,8 +1864,8 @@ out: } } - log_debug("Using command index %d id %s enum %d.", - best_i, commands[best_i].command_id, commands[best_i].command_enum); + log_debug("Recognised command %s (id %d / enum %d).", + commands[best_i].command_id, best_i, commands[best_i].command_enum); return &commands[best_i]; } @@ -2873,9 +2873,9 @@ int lvm_run_command(struct cmd_context *cmd, int argc, char **argv) goto_out; init_dmeventd_monitor(monitoring); - log_debug("Processing: %s", cmd->cmd_line); + log_debug("Processing command: %s", cmd->cmd_line); log_debug("Command pid: %d", getpid()); - log_debug("system ID: %s", cmd->system_id ? : ""); + log_debug("System ID: %s", cmd->system_id ? : ""); #ifdef O_DIRECT_SUPPORT log_debug("O_DIRECT will be used"); diff --git a/tools/toollib.c b/tools/toollib.c index 289852590..9b8834148 100644 --- a/tools/toollib.c +++ b/tools/toollib.c @@ -1967,7 +1967,7 @@ static int _process_vgnameid_list(struct cmd_context *cmd, uint32_t read_flags, (!dm_list_empty(arg_tags) && str_list_match_list(arg_tags, &vg->tags, NULL))) && select_match_vg(cmd, handle, vg) && _select_matches(handle)) { - log_very_verbose("Process single VG %s", vg_name); + log_very_verbose("Processing VG %s %s", vg_name, vg_uuid ? uuid : ""); ret = process_single_vg(cmd, vg_name, vg, handle); _update_selection_result(handle, &whole_selected); @@ -2231,7 +2231,7 @@ int process_each_vg(struct cmd_context *cmd, * . A VG name is specified which may refer to one * of multiple VGs on the system with that name. */ - log_debug("Get list of VGs on system"); + log_very_verbose("Obtaining the complete list of VGs to process"); if (!get_vgnameids(cmd, &vgnameids_on_system, NULL, include_internal)) { ret_max = ECMD_FAILED; @@ -3733,7 +3733,7 @@ int process_each_lv(struct cmd_context *cmd, * . A VG name is specified which may refer to one * of multiple VGs on the system with that name. */ - log_debug("Get list of VGs on system"); + log_very_verbose("Obtaining the complete list of VGs before processing their LVs"); if (!get_vgnameids(cmd, &vgnameids_on_system, NULL, 0)) { ret_max = ECMD_FAILED;