/* * Copyright (c) International Business Machines Corp., 2006 * * This program is free software; you can redistribute it and/or modify * it under the terms of the GNU General Public License as published by * the Free Software Foundation; either version 2 of the License, or * (at your option) any later version. * * This program is distributed in the hope that it will be useful, * but WITHOUT ANY WARRANTY; without even the implied warranty of * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See * the GNU General Public License for more details. * * You should have received a copy of the GNU General Public License * along with this program; if not, write to the Free Software * Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA * * Author: Artem Bityutskiy (Битюцкий Артём) */ /* * UBI attaching sub-system. * * This sub-system is responsible for attaching MTD devices and it also * implements flash media scanning. * * The attaching information is represented by a &struct ubi_attach_info' * object. Information about volumes is represented by &struct ubi_ainf_volume * objects which are kept in volume RB-tree with root at the @volumes field. * The RB-tree is indexed by the volume ID. * * Logical eraseblocks are represented by &struct ubi_ainf_peb objects. These * objects are kept in per-volume RB-trees with the root at the corresponding * &struct ubi_ainf_volume object. To put it differently, we keep an RB-tree of * per-volume objects and each of these objects is the root of RB-tree of * per-LEB objects. * * Corrupted physical eraseblocks are put to the @corr list, free physical * eraseblocks are put to the @free list and the physical eraseblock to be * erased are put to the @erase list. * * About corruptions * ~~~~~~~~~~~~~~~~~ * * UBI protects EC and VID headers with CRC-32 checksums, so it can detect * whether the headers are corrupted or not. Sometimes UBI also protects the * data with CRC-32, e.g., when it executes the atomic LEB change operation, or * when it moves the contents of a PEB for wear-leveling purposes. * * UBI tries to distinguish between 2 types of corruptions. * * 1. Corruptions caused by power cuts. These are expected corruptions and UBI * tries to handle them gracefully, without printing too many warnings and * error messages. The idea is that we do not lose important data in these * cases - we may lose only the data which were being written to the media just * before the power cut happened, and the upper layers (e.g., UBIFS) are * supposed to handle such data losses (e.g., by using the FS journal). * * When UBI detects a corruption (CRC-32 mismatch) in a PEB, and it looks like * the reason is a power cut, UBI puts this PEB to the @erase list, and all * PEBs in the @erase list are scheduled for erasure later. * * 2. Unexpected corruptions which are not caused by power cuts. During * attaching, such PEBs are put to the @corr list and UBI preserves them. * Obviously, this lessens the amount of available PEBs, and if at some point * UBI runs out of free PEBs, it switches to R/O mode. UBI also loudly informs * about such PEBs every time the MTD device is attached. * * However, it is difficult to reliably distinguish between these types of * corruptions and UBI's strategy is as follows (in case of attaching by * scanning). UBI assumes corruption type 2 if the VID header is corrupted and * the data area does not contain all 0xFFs, and there were no bit-flips or * integrity errors (e.g., ECC errors in case of NAND) while reading the data * area. Otherwise UBI assumes corruption type 1. So the decision criteria * are as follows. * o If the data area contains only 0xFFs, there are no data, and it is safe * to just erase this PEB - this is corruption type 1. * o If the data area has bit-flips or data integrity errors (ECC errors on * NAND), it is probably a PEB which was being erased when power cut * happened, so this is corruption type 1. However, this is just a guess, * which might be wrong. * o Otherwise this is corruption type 2. */ #include #include #include #include #include #include "ubi.h" static int self_check_ai(struct ubi_device *ubi, struct ubi_attach_info *ai); /* Temporary variables used during scanning */ static struct ubi_ec_hdr *ech; static struct ubi_vid_hdr *vidh; /** * add_to_list - add physical eraseblock to a list. * @ai: attaching information * @pnum: physical eraseblock number to add * @vol_id: the last used volume id for the PEB * @lnum: the last used LEB number for the PEB * @ec: erase counter of the physical eraseblock * @to_head: if not zero, add to the head of the list * @list: the list to add to * * This function allocates a 'struct ubi_ainf_peb' object for physical * eraseblock @pnum and adds it to the "free", "erase", or "alien" lists. * It stores the @lnum and @vol_id alongside, which can both be * %UBI_UNKNOWN if they are not available, not readable, or not assigned. * If @to_head is not zero, PEB will be added to the head of the list, which * basically means it will be processed first later. E.g., we add corrupted * PEBs (corrupted due to power cuts) to the head of the erase list to make * sure we erase them first and get rid of corruptions ASAP. This function * returns zero in case of success and a negative error code in case of * failure. */ static int add_to_list(struct ubi_attach_info *ai, int pnum, int vol_id, int lnum, int ec, int to_head, struct list_head *list) { struct ubi_ainf_peb *aeb; if (list == &ai->free) { dbg_bld("add to free: PEB %d, EC %d", pnum, ec); } else if (list == &ai->erase) { dbg_bld("add to erase: PEB %d, EC %d", pnum, ec); } else if (list == &ai->alien) { dbg_bld("add to alien: PEB %d, EC %d", pnum, ec); ai->alien_peb_count += 1; } else BUG(); aeb = kmem_cache_alloc(ai->aeb_slab_cache, GFP_KERNEL); if (!aeb) return -ENOMEM; aeb->pnum = pnum; aeb->vol_id = vol_id; aeb->lnum = lnum; aeb->ec = ec; if (to_head) list_add(&aeb->u.list, list); else list_add_tail(&aeb->u.list, list); return 0; } /** * add_corrupted - add a corrupted physical eraseblock. * @ai: attaching information * @pnum: physical eraseblock number to add * @ec: erase counter of the physical eraseblock * * This function allocates a 'struct ubi_ainf_peb' object for a corrupted * physical eraseblock @pnum and adds it to the 'corr' list. The corruption * was presumably not caused by a power cut. Returns zero in case of success * and a negative error code in case of failure. */ static int add_corrupted(struct ubi_attach_info *ai, int pnum, int ec) { struct ubi_ainf_peb *aeb; dbg_bld("add to corrupted: PEB %d, EC %d", pnum, ec); aeb = kmem_cache_alloc(ai->aeb_slab_cache, GFP_KERNEL); if (!aeb) return -ENOMEM; ai->corr_peb_count += 1; aeb->pnum = pnum; aeb->ec = ec; list_add(&aeb->u.list, &ai->corr); return 0; } /** * validate_vid_hdr - check volume identifier header. * @ubi: UBI device description object * @vid_hdr: the volume identifier header to check * @av: information about the volume this logical eraseblock belongs to * @pnum: physical eraseblock number the VID header came from * * This function checks that data stored in @vid_hdr is consistent. Returns * non-zero if an inconsistency was found and zero if not. * * Note, UBI does sanity check of everything it reads from the flash media. * Most of the checks are done in the I/O sub-system. Here we check that the * information in the VID header is consistent to the information in other VID * headers of the same volume. */ static int validate_vid_hdr(const struct ubi_device *ubi, const struct ubi_vid_hdr *vid_hdr, const struct ubi_ainf_volume *av, int pnum) { int vol_type = vid_hdr->vol_type; int vol_id = be32_to_cpu(vid_hdr->vol_id); int used_ebs = be32_to_cpu(vid_hdr->used_ebs); int data_pad = be32_to_cpu(vid_hdr->data_pad); if (av->leb_count != 0) { int av_vol_type; /* * This is not the first logical eraseblock belonging to this * volume. Ensure that the data in its VID header is consistent * to the data in previous logical eraseblock headers. */ if (vol_id != av->vol_id) { ubi_err(ubi, "inconsistent vol_id"); goto bad; } if (av->vol_type == UBI_STATIC_VOLUME) av_vol_type = UBI_VID_STATIC; else av_vol_type = UBI_VID_DYNAMIC; if (vol_type != av_vol_type) { ubi_err(ubi, "inconsistent vol_type"); goto bad; } if (used_ebs != av->used_ebs) { ubi_err(ubi, "inconsistent used_ebs"); goto bad; } if (data_pad != av->data_pad) { ubi_err(ubi, "inconsistent data_pad"); goto bad; } } return 0; bad: ubi_err(ubi, "inconsistent VID header at PEB %d", pnum); ubi_dump_vid_hdr(vid_hdr); ubi_dump_av(av); return -EINVAL; } /** * add_volume - add volume to the attaching information. * @ai: attaching information * @vol_id: ID of the volume to add * @pnum: physical eraseblock number * @vid_hdr: volume identifier header * * If the volume corresponding to the @vid_hdr logical eraseblock is already * present in the attaching information, this function does nothing. Otherwise * it adds corresponding volume to the attaching information. Returns a pointer * to the allocated "av" object in case of success and a negative error code in * case of failure. */ static struct ubi_ainf_volume *add_volume(struct ubi_attach_info *ai, int vol_id, int pnum, const struct ubi_vid_hdr *vid_hdr) { struct ubi_ainf_volume *av; struct rb_node **p = &ai->volumes.rb_node, *parent = NULL; ubi_assert(vol_id == be32_to_cpu(vid_hdr->vol_id)); /* Walk the volume RB-tree to look if this volume is already present */ while (*p) { parent = *p; av = rb_entry(parent, struct ubi_ainf_volume, rb); if (vol_id == av->vol_id) return av; if (vol_id > av->vol_id) p = &(*p)->rb_left; else p = &(*p)->rb_right; } /* The volume is absent - add it */ av = kmalloc(sizeof(struct ubi_ainf_volume), GFP_KERNEL); if (!av) return ERR_PTR(-ENOMEM); av->highest_lnum = av->leb_count = 0; av->vol_id = vol_id; av->root = RB_ROOT; av->used_ebs = be32_to_cpu(vid_hdr->used_ebs); av->data_pad = be32_to_cpu(vid_hdr->data_pad); av->compat = vid_hdr->compat; av->vol_type = vid_hdr->vol_type == UBI_VID_DYNAMIC ? UBI_DYNAMIC_VOLUME : UBI_STATIC_VOLUME; if (vol_id > ai->highest_vol_id) ai->highest_vol_id = vol_id; rb_link_node(&av->rb, parent, p); rb_insert_color(&av->rb, &ai->volumes); ai->vols_found += 1; dbg_bld("added volume %d", vol_id); return av; } /** * ubi_compare_lebs - find out which logical eraseblock is newer. * @ubi: UBI device description object * @aeb: first logical eraseblock to compare * @pnum: physical eraseblock number of the second logical eraseblock to * compare * @vid_hdr: volume identifier header of the second logical eraseblock * * This function compares 2 copies of a LEB and informs which one is newer. In * case of success this function returns a positive value, in case of failure, a * negative error code is returned. The success return codes use the following * bits: * o bit 0 is cleared: the first PEB (described by @aeb) is newer than the * second PEB (described by @pnum and @vid_hdr); * o bit 0 is set: the second PEB is newer; * o bit 1 is cleared: no bit-flips were detected in the newer LEB; * o bit 1 is set: bit-flips were detected in the newer LEB; * o bit 2 is cleared: the older LEB is not corrupted; * o bit 2 is set: the older LEB is corrupted. */ int ubi_compare_lebs(struct ubi_device *ubi, const struct ubi_ainf_peb *aeb, int pnum, const struct ubi_vid_hdr *vid_hdr) { int len, err, second_is_newer, bitflips = 0, corrupted = 0; uint32_t data_crc, crc; struct ubi_vid_hdr *vh = NULL; unsigned long long sqnum2 = be64_to_cpu(vid_hdr->sqnum); if (sqnum2 == aeb->sqnum) { /* * This must be a really ancient UBI image which has been * created before sequence numbers support has been added. At * that times we used 32-bit LEB versions stored in logical * eraseblocks. That was before UBI got into mainline. We do not * support these images anymore. Well, those images still work, * but only if no unclean reboots happened. */ ubi_err(ubi, "unsupported on-flash UBI format"); return -EINVAL; } /* Obviously the LEB with lower sequence counter is older */ second_is_newer = (sqnum2 > aeb->sqnum); /* * Now we know which copy is newer. If the copy flag of the PEB with * newer version is not set, then we just return, otherwise we have to * check data CRC. For the second PEB we already have the VID header, * for the first one - we'll need to re-read it from flash. * * Note: this may be optimized so that we wouldn't read twice. */ if (second_is_newer) { if (!vid_hdr->copy_flag) { /* It is not a copy, so it is newer */ dbg_bld("second PEB %d is newer, copy_flag is unset", pnum); return 1; } } else { if (!aeb->copy_flag) { /* It is not a copy, so it is newer */ dbg_bld("first PEB %d is newer, copy_flag is unset", pnum); return bitflips << 1; } vh = ubi_zalloc_vid_hdr(ubi, GFP_KERNEL); if (!vh) return -ENOMEM; pnum = aeb->pnum; err = ubi_io_read_vid_hdr(ubi, pnum, vh, 0); if (err) { if (err == UBI_IO_BITFLIPS) bitflips = 1; else { ubi_err(ubi, "VID of PEB %d header is bad, but it was OK earlier, err %d", pnum, err); if (err > 0) err = -EIO; goto out_free_vidh; } } vid_hdr = vh; } /* Read the data of the copy and check the CRC */ len = be32_to_cpu(vid_hdr->data_size); mutex_lock(&ubi->buf_mutex); err = ubi_io_read_data(ubi, ubi->peb_buf, pnum, 0, len); if (err && err != UBI_IO_BITFLIPS && !mtd_is_eccerr(err)) goto out_unlock; data_crc = be32_to_cpu(vid_hdr->data_crc); crc = crc32(UBI_CRC32_INIT, ubi->peb_buf, len); if (crc != data_crc) { dbg_bld("PEB %d CRC error: calculated %#08x, must be %#08x", pnum, crc, data_crc); corrupted = 1; bitflips = 0; second_is_newer = !second_is_newer; } else { dbg_bld("PEB %d CRC is OK", pnum); bitflips |= !!err; } mutex_unlock(&ubi->buf_mutex); ubi_free_vid_hdr(ubi, vh); if (second_is_newer) dbg_bld("second PEB %d is newer, copy_flag is set", pnum); else dbg_bld("first PEB %d is newer, copy_flag is set", pnum); return second_is_newer | (bitflips << 1) | (corrupted << 2); out_unlock: mutex_unlock(&ubi->buf_mutex); out_free_vidh: ubi_free_vid_hdr(ubi, vh); return err; } /** * ubi_add_to_av - add used physical eraseblock to the attaching information. * @ubi: UBI device description object * @ai: attaching information * @pnum: the physical eraseblock number * @ec: erase counter * @vid_hdr: the volume identifier header * @bitflips: if bit-flips were detected when this physical eraseblock was read * * This function adds information about a used physical eraseblock to the * 'used' tree of the corresponding volume. The function is rather complex * because it has to handle cases when this is not the first physical * eraseblock belonging to the same logical eraseblock, and the newer one has * to be picked, while the older one has to be dropped. This function returns * zero in case of success and a negative error code in case of failure. */ int ubi_add_to_av(struct ubi_device *ubi, struct ubi_attach_info *ai, int pnum, int ec, const struct ubi_vid_hdr *vid_hdr, int bitflips) { int err, vol_id, lnum; unsigned long long sqnum; struct ubi_ainf_volume *av; struct ubi_ainf_peb *aeb; struct rb_node **p, *parent = NULL; vol_id = be32_to_cpu(vid_hdr->vol_id); lnum = be32_to_cpu(vid_hdr->lnum); sqnum = be64_to_cpu(vid_hdr->sqnum); dbg_bld("PEB %d, LEB %d:%d, EC %d, sqnum %llu, bitflips %d", pnum, vol_id, lnum, ec, sqnum, bitflips); av = add_volume(ai, vol_id, pnum, vid_hdr); if (IS_ERR(av)) return PTR_ERR(av); if (ai->max_sqnum < sqnum) ai->max_sqnum = sqnum; /* * Walk the RB-tree of logical eraseblocks of volume @vol_id to look * if this is the first instance of this logical eraseblock or not. */ p = &av->root.rb_node; while (*p) { int cmp_res; parent = *p; aeb = rb_entry(parent, struct ubi_ainf_peb, u.rb); if (lnum != aeb->lnum) { if (lnum < aeb->lnum) p = &(*p)->rb_left; else p = &(*p)->rb_right; continue; } /* * There is already a physical eraseblock describing the same * logical eraseblock present. */ dbg_bld("this LEB already exists: PEB %d, sqnum %llu, EC %d", aeb->pnum, aeb->sqnum, aeb->ec); /* * Make sure that the logical eraseblocks have different * sequence numbers. Otherwise the image is bad. * * However, if the sequence number is zero, we assume it must * be an ancient UBI image from the era when UBI did not have * sequence numbers. We still can attach these images, unless * there is a need to distinguish between old and new * eraseblocks, in which case we'll refuse the image in * 'ubi_compare_lebs()'. In other words, we attach old clean * images, but refuse attaching old images with duplicated * logical eraseblocks because there was an unclean reboot. */ if (aeb->sqnum == sqnum && sqnum != 0) { ubi_err(ubi, "two LEBs with same sequence number %llu", sqnum); ubi_dump_aeb(aeb, 0); ubi_dump_vid_hdr(vid_hdr); return -EINVAL; } /* * Now we have to drop the older one and preserve the newer * one. */ cmp_res = ubi_compare_lebs(ubi, aeb, pnum, vid_hdr); if (cmp_res < 0) return cmp_res; if (cmp_res & 1) { /* * This logical eraseblock is newer than the one * found earlier. */ err = validate_vid_hdr(ubi, vid_hdr, av, pnum); if (err) return err; err = add_to_list(ai, aeb->pnum, aeb->vol_id, aeb->lnum, aeb->ec, cmp_res & 4, &ai->erase); if (err) return err; aeb->ec = ec; aeb->pnum = pnum; aeb->vol_id = vol_id; aeb->lnum = lnum; aeb->scrub = ((cmp_res & 2) || bitflips); aeb->copy_flag = vid_hdr->copy_flag; aeb->sqnum = sqnum; if (av->highest_lnum == lnum) av->last_data_size = be32_to_cpu(vid_hdr->data_size); return 0; } else { /* * This logical eraseblock is older than the one found * previously. */ return add_to_list(ai, pnum, vol_id, lnum, ec, cmp_res & 4, &ai->erase); } } /* * We've met this logical eraseblock for the first time, add it to the * attaching information. */ err = validate_vid_hdr(ubi, vid_hdr, av, pnum); if (err) return err; aeb = kmem_cache_alloc(ai->aeb_slab_cache, GFP_KERNEL); if (!aeb) return -ENOMEM; aeb->ec = ec; aeb->pnum = pnum; aeb->vol_id = vol_id; aeb->lnum = lnum; aeb->scrub = bitflips; aeb->copy_flag = vid_hdr->copy_flag; aeb->sqnum = sqnum; if (av->highest_lnum <= lnum) { av->highest_lnum = lnum; av->last_data_size = be32_to_cpu(vid_hdr->data_size); } av->leb_count += 1; rb_link_node(&aeb->u.rb, parent, p); rb_insert_color(&aeb->u.rb, &av->root); return 0; } /** * ubi_find_av - find volume in the attaching information. * @ai: attaching information * @vol_id: the requested volume ID * * This function returns a pointer to the volume description or %NULL if there * are no data about this volume in the attaching information. */ struct ubi_ainf_volume *ubi_find_av(const struct ubi_attach_info *ai, int vol_id) { struct ubi_ainf_volume *av; struct rb_node *p = ai->volumes.rb_node; while (p) { av = rb_entry(p, struct ubi_ainf_volume, rb); if (vol_id == av->vol_id) return av; if (vol_id > av->vol_id) p = p->rb_left; else p = p->rb_right; } return NULL; } /** * ubi_remove_av - delete attaching information about a volume. * @ai: attaching information * @av: the volume attaching information to delete */ void u
import os
import pprint
import re
import sys
import time

import paramiko
from scp import SCPClient

import functest.utils.functest_utils as ft_utils
import functest.utils.openstack_utils as os_utils
FUNCTEST_REPO = ft_utils.FUNCTEST_REPO

NAME_VM_1 = ft_utils.get_functest_config('vping.vm_name_1')
NAME_VM_2 = ft_utils.get_functest_config('vping.vm_name_2')

VM_BOOT_TIMEOUT = 180
VM_DELETE_TIMEOUT = 100
PING_TIMEOUT = ft_utils.get_functest_config('vping.ping_timeout')

GLANCE_IMAGE_NAME = ft_utils.get_functest_config('vping.image_name')
GLANCE_IMAGE_FILENAME = \
    ft_utils.get_functest_config('general.openstack.image_file_name')
GLANCE_IMAGE_FORMAT = \
    ft_utils.get_functest_config('general.openstack.image_disk_format')
GLANCE_IMAGE_PATH = \
    ft_utils.get_functest_config('general.directories.dir_functest_data') + \
    "/" + GLANCE_IMAGE_FILENAME


FLAVOR = ft_utils.get_functest_config('vping.vm_flavor')

# NEUTRON Private Network parameters
PRIVATE_NET_NAME = \
    ft_utils.get_functest_config('vping.vping_private_net_name')
PRIVATE_SUBNET_NAME = \
    ft_utils.get_functest_config('vping.vping_private_subnet_name')
PRIVATE_SUBNET_CIDR = \
    ft_utils.get_functest_config('vping.vping_private_subnet_cidr')
ROUTER_NAME = ft_utils.get_functest_config('vping.vping_router_name')

SECGROUP_NAME = ft_utils.get_functest_config('vping.vping_sg_name')
SECGROUP_DESCR = ft_utils.get_functest_config('vping.vping_sg_descr')


neutron_client = None
glance_client = None
nova_client = None
logger = None

pp = pprint.PrettyPrinter(indent=4)


def pMsg(value):
    """pretty printing"""
    pp.pprint(value)


def check_repo_exist():
    if not os.path.exists(FUNCTEST_REPO):
        logger.error("Functest repository not found '%s'" % FUNCTEST_REPO)
        exit(-1)


def get_vmname_1():
    return NAME_VM_1


def get_vmname_2():
    return NAME_VM_2


def init(vping_logger):
    global nova_client
    nova_client = os_utils.get_nova_client()
    global neutron_client
    neutron_client = os_utils.get_neutron_client()
    global glance_client
    glance_client = os_utils.get_glance_client()
    global logger
    logger = vping_logger


def waitVmActive(nova, vm):

    # sleep and wait for VM status change
    sleep_time = 3
    count = VM_BOOT_TIMEOUT / sleep_time
    while True:
        status = os_utils.get_instance_status(nova, vm)
        logger.debug("Status: %s" % status)
        if status == "ACTIVE":
            return True
        if status == "ERROR" or status == "error":
            return False
        if count == 0:
            logger.debug("Booting a VM timed out...")
            return False
        count -= 1
        time.sleep(sleep_time)
    return False


def create_security_group():
    sg_id = os_utils.get_security_group_id(neutron_client,
                                           SECGROUP_NAME)
    if sg_id != '':
        logger.info("Using existing security group '%s'..." % SECGROUP_NAME)
    else:
        logger.info("Creating security group  '%s'..." % SECGROUP_NAME)
        SECGROUP = os_utils.create_security_group(neutron_client,
                                                  SECGROUP_NAME,
                                                  SECGROUP_DESCR)
        if not SECGROUP:
            logger.error("Failed to create the security group...")
            return False

        sg_id = SECGROUP['id']

        logger.debug("Security group '%s' with ID=%s created successfully."
                     % (SECGROUP['name'], sg_id))

        logger.debug("Adding ICMP rules in security group '%s'..."
                     % SECGROUP_NAME)
        if not os_utils.create_secgroup_rule(neutron_client, sg_id,
                                             'ingress', 'icmp'):
            logger.error("Failed to create the security group rule...")
            return False

        logger.debug("Adding SSH rules in security group '%s'..."
                     % SECGROUP_NAME)
        if not os_utils.create_secgroup_rule(neutron_client, sg_id,
                                             'ingress', 'tcp',
                                             '22', '22'):
            logger.error("Failed to create the security group rule...")
            return False

        if not os_utils.create_secgroup_rule(
                neutron_client, sg_id, 'egress', 'tcp', '22', '22'):
            logger.error("Failed to create the security group rule...")
            return False
    return sg_id


def create_image():
    _, image_id = os_utils.get_or_create_image(GLANCE_IMAGE_NAME,
                                               GLANCE_IMAGE_PATH,
                                               GLANCE_IMAGE_FORMAT)
    if not image_id:
        exit(-1)

    return image_id


def get_flavor():
    EXIT_CODE = -1

    # Check if the given flavor exists
    try:
        flavor = nova_client.flavors.find(name=FLAVOR)
        logger.info("Using existing Flavor '%s'..." % FLAVOR)
        return flavor
    except:
        logger.error("Flavor '%s' not found." % FLAVOR)
        logger.info("Available f