Debug level logs are getting printed when log level is set WARN

[MohammadNC]

Hi Team,

Debug level logs are getting printed when log level is set WARN, please refer the below log4j configs and sample java code where Debug logs are getting printed.

<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
    <Properties>
        <Property name="sourceApp">${bundle:application:spring.application.name}</Property>
        <Property name="sourceAppVersion">${bundle:application:spring.application.version}</Property>
        <Property name="subsystem">${bundle:application:spring.module.name}</Property>
   </Properties>
   <Appenders>
      <Console name="console" target="SYSTEM_OUT">
          <JsonTemplateLayout eventTemplateUri="classpath:JsonLayout.json">
              <EventTemplateAdditionalField key="messageId" value="$${ctx:x-request-id:-}" />
              <EventTemplateAdditionalField key="messageTimestamp" value="$${date:YYYY-MM-dd'T'HH:mm:ss.SSSZ}" />
              <EventTemplateAdditionalField key="application" value="$${env:APP_NAME}" />
              <EventTemplateAdditionalField key="microservice" value="$${env:MICROSERVICE_NAME}" />
              <EventTemplateAdditionalField key="engVersion" value="$${env:ENGINEERING_VERSION}" />
              <EventTemplateAdditionalField key="mktgVersion" value="$${env:MARKETING_VERSION}" />
              <EventTemplateAdditionalField key="namespace" value="$${env:K8S_NAMESPACE}" />
              <EventTemplateAdditionalField key="node" value="$${env:K8S_NODE}" />
              <EventTemplateAdditionalField key="pod" value="$${env:POD_NAME}" />
              <EventTemplateAdditionalField key="subsystem" value="${subsystem}" />
              <EventTemplateAdditionalField key="instanceType" value="prod" />
              <EventTemplateAdditionalField key="processId" value="$${sys:PID}" />

          </JsonTemplateLayout>
      </Console>
   </Appenders>
    <Loggers>
        <Root level="info" additivity="false">
            <AppenderRef ref="console" />
        </Root>
    </Loggers>
</Configuration>

java code:

import java.util.List;
import java.util.Map;
import java.util.Objects;
import java.util.Set;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.springframework.http.HttpHeaders;

public class LciUtility {

    private static final Logger logger = LogManager.getLogger(LciUtility.class.getClass());

    static PeerLciLocalCache peerLciLocalCache = null;

    /**
     * populateRelCapacityInPriorityMap method updates the priority map in which it calculates the
     * effective and relative capacity of each destination weight and puts it back
     * in the map.
     * 
     * @param priorityMap
     * @param routeList
     * @param isInterPlmn
     */
    public static void populateRelCapacityInPriorityMap(Map<Integer, Set<DestinationIndexAndCapacity>> priorityMap,
            List<DestinationWeight> routeList, boolean isInterPlmn, StreamInfo streamInfo) {

        if (logger.isDebugEnabled()) {
            logger.debug("IN: LciUtility::populateRelCapacityInPriorityMap() priorityMap before update ::{} ", priorityMap);
        }

        int index = 0;
        DestinationWeight destWt = null;
        //int load = 0;
        PeerLciData data = null;
        int totalCapacity = 0;
        DestinationIndexAndCapacity forwardRouteIndex = streamInfo.getDestinationList().getFwdRouteIndex();
        boolean needForwardRouteIndexUpdate = false;

        if(Objects.nonNull(forwardRouteIndex))
        {
            needForwardRouteIndexUpdate = true;
        }

        peerLciLocalCache = BeanUtil.getBean(PeerLciLocalCache.class);
        for (Map.Entry<Integer, Set<DestinationIndexAndCapacity>> entry : priorityMap.entrySet()) {

            totalCapacity = 0;
            Set<DestinationIndexAndCapacity> indexCapSet = entry.getValue();

            //Skipping the relative capacity calculation if set has only one element. Relative capacity for single member will
            //always be 100
            if(indexCapSet.size() == 1) {
                if (logger.isDebugEnabled()) {
                    logger.debug("DestinationIndexAndCapacity set size is 1 for priority :{}", entry.getKey());
                }
                //indexCapSet.stream().findFirst().get().setCapacity(100);
                DestinationIndexAndCapacity indexCap = indexCapSet.stream().findFirst().get();
                indexCap.setCapacity(100);
                if(needForwardRouteIndexUpdate && forwardRouteIndex.getIndex().equals(indexCap.getIndex())) {
                    forwardRouteIndex.setCapacity(indexCap.getCapacity());
                    if (logger.isDebugEnabled()) {
                        logger.debug(
                                "LciUtility::populateRelCapacityInPriorityMap()::forwardRouteIndex After update : {}",
                                forwardRouteIndex);
                    }
                    needForwardRouteIndexUpdate = false;
                }
                continue;
            }

            for (DestinationIndexAndCapacity destIndexCapcity : indexCapSet) {
                index = destIndexCapcity.getIndex();
                destWt = routeList.get(index);

                if (logger.isDebugEnabled()) {

                    logger.debug("Host is {} RemoteHost {}, isInterPlmn {}", destWt.getDestination().getHost(),destWt.getIsRemoteapp(),isInterPlmn);
                }

                data = getPeerLciData(destWt, isInterPlmn, streamInfo.getNfServiceType());

                if (Objects.isNull(data)) {
                    logger.debug("OUT: LciUtility::populateRelCapacityInPriorityMap():: LCI data is not present. ");
                    continue;
                } else {

                    if (logger.isDebugEnabled()) {
                        logger.debug("LciUtility::populateRelCapacityInPriorityMap():: value of load from cache is :: {} ", data);
                        }
                    destIndexCapcity.setCapacity(calculateEffectiveCapacity(data.getP().getL(), destIndexCapcity.getCapacity()));
                    totalCapacity = totalCapacity + destIndexCapcity.getCapacity();
                }
            }

            // setting the relative capacity of all weights
            if (totalCapacity > 0) {
                for (DestinationIndexAndCapacity destIndexCapcity : indexCapSet) {
                    destIndexCapcity.populateRelativeCapacity(totalCapacity);
                    if(needForwardRouteIndexUpdate && forwardRouteIndex.getIndex().equals(destIndexCapcity.getIndex())) {
                        forwardRouteIndex.setCapacity(destIndexCapcity.getCapacity());
                        if (logger.isDebugEnabled()) {
                            logger.debug(
                                    "LciUtility::populateRelCapacityInPriorityMap()::forwardRouteIndex After update : {}",
                                    forwardRouteIndex);
                        }
                        needForwardRouteIndexUpdate = false;
                    }
                }
            }
        }

        if (logger.isDebugEnabled()) {
            logger.debug("OUT: LciUtility::populateRelCapacityInPriorityMap() priorityMap after update ::{} ",
                    priorityMap);
        }
    }

    /**
     * This method is calculating the effective capacity.
     * 
     * @param load
     * @param capacity
     * @return
     */
    private static int calculateEffectiveCapacity(int load, int capacity) {
            int effectiveCapacity = ((100 - load) * capacity) / 100;  // 50*5000/100
            logger.debug("Original Calacity is {}, Effective Capacity is {}", capacity, effectiveCapacity);
            return effectiveCapacity;
    }

    /**
     * This method is fetch the LCI data from local cache for different request type.
     * 
     * @param destWt
     * @param isInterPlmn
     * @return
     */
    public static PeerLciData getPeerLciData(DestinationWeight destWt, boolean isInterPlmn, String srvName) {
        logger.debug("IN: LciUtility::getPeerLciData()");

        if(Objects.isNull(peerLciLocalCache)) {
            peerLciLocalCache = BeanUtil.getBean(PeerLciLocalCache.class);
        }

        PeerLciData data = null;
        if(isInterPlmn) {
            data = peerLciLocalCache.getPeerLciBySeppFqdn(destWt.getDestination().getHost());

            if (logger.isDebugEnabled()) {
                logger.debug("PeerLciData for InterPLMN {}", data);
                }
        } else if (destWt.getIsRemoteapp() == true) {
            data = peerLciLocalCache.getPeerLciByappFqdn(CommonUtils.getSelectedDestinationFqdn(destWt.getDestination().getHost()));

            if (logger.isDebugEnabled()) {
            logger.debug("PeerLciData for Interapp {}", data);
            }
        } else if (destWt.getIsRemoteapp() == false) {
            if (logger.isDebugEnabled()) {
                logger.debug("instanceId is {} , svcInstanceId is {}, srvName : {}", destWt.getOcappw_nf_instance_id(),
                        destWt.getOcappw_service_instance_id(), srvName);
            }

            if(srvName.equalsIgnoreCase(CommonConstants.getDefaultServiceType()) || srvName.equalsIgnoreCase(CommonConstants.getUnknown())) {
                data = peerLciLocalCache.getPeerLciByNfInstAndSvcInst(destWt.getOcappw_nf_instance_id(), null);
            } else {
                data = peerLciLocalCache.getPeerLciByNfInstAndSvcInst(destWt.getOcappw_nf_instance_id(),
                        destWt.getOcappw_service_instance_id());
            }

        } 
        if (logger.isDebugEnabled()) {
            logger.debug("OUT: LciUtility::getPeerLciData(), PeerLciData fetched::{}", data);
        }
        return data;
    }

    public static PeerLciData getPeerLciData(LciHeader lciHeader, String instanceId) {

        Map<String, String> lcScope = lciHeader.getLcScope();
        if (lcScope == null || lcScope.size() < 1) {

            logger.debug("OUT: LciUtility::getPeerLciData() lcScope is Null or Empty key");
            return null;
        } else {
            String lcScopeKey = null;
            String nfInstId = instanceId;
            String svcInstId = CommonConstants.DEFAULT;
            String lcScopeValue = null;

            for (Map.Entry<String, String> entry : lcScope.entrySet()) {
                lcScopeKey = entry.getKey();

                if (lcScopeKey.equals(CommonConstants.app_FQDN)) {

                    lcScopeValue = entry.getValue();

                    if (logger.isDebugEnabled()) {
                        logger.debug(
                                "OUT: LciUtility::getPeerLciData(lciHeader, instanceId). Lci scope is  {}, value : {}",
                                lcScopeKey, lcScopeValue);
                    }
                    return peerLciLocalCache.getPeerLciByappFqdn(lcScopeValue);
                }
                if (lcScopeKey.equals(CommonConstants.SEPP_FQDN)) {
                    lcScopeValue = entry.getValue();
                    if (logger.isDebugEnabled()) {
                        logger.debug(
                                "OUT: LciUtility::getPeerLciData(lciHeader, instanceId). Lci scope is  {}, value : {}",
                                lcScopeKey, lcScopeValue);
                    }
                    return peerLciLocalCache.getPeerLciBySeppFqdn(lcScopeValue);
                } else {
                    if (lcScopeKey.equals(CommonConstants.NF_INSTANCE)) {
                        nfInstId = entry.getValue();
                        logger.debug("LciUtility::getPeerLciData(lciHeader, instanceId). nfInstId : {}", nfInstId);
                        if (StringUtils.isEmpty(nfInstId)) {
                            nfInstId = instanceId;
                        }

                    } else if (lcScopeKey
                            .equals(CommonConstants.NF_SVC_INSTANCE)) {
                        svcInstId = entry.getValue();
                        logger.debug("LciUtility::getPeerLciData(lciHeader, instanceId). svcInstId : {}", svcInstId);
                    }

                }

            }

            if (StringUtils.isEmpty(nfInstId)) {
                nfInstId = instanceId;
            }
            logger.debug("OUT: LciUtility::getPeerLciData(lciHeader, instanceId)");
            return peerLciLocalCache.getPeerLciByNfInstAndSvcInst(nfInstId, svcInstId);
        }

    }

    public static void updateLciHeader(StreamInfo streamInfo, HttpHeaders headers, Event eventType) {

        logger.debug("IN: LciUtility::updateLciHeader()");

        LciConfiguration lciConfiguration = BeanUtil.getBean(LciConfiguration.class);

        if (headers.containsKey(CommonConstants.LCI_HEADER_NAME) == false) {
            logger.debug("OUT: LciUtility::updateLciHeader()");
            return;
        }

        if (lciConfiguration.isRelayPeerLci() == false) {
            headers.remove(CommonConstants.LCI_HEADER_NAME);
            logger.debug("OUT: LciUtility::updateLciHeader()");
            return;
        }

        LciContext lciContext = streamInfo.getLciContext();
        List<LciHeader> lciHeaders = eventType.equals(Event.Request) ? lciContext.getReqLciHeader()
                : lciContext.getRspLciHeader();

        if(lciHeaders == null || lciHeaders.isEmpty()) {
            logger.debug("OUT: LciUtility::lciHeaders is null or Empty");
            return;
        }

        headers.remove(CommonConstants.LCI_HEADER_NAME);

        Map<String, String> lcScope;
        String lcScopeKey;
        String lciheader;
        //boolean isPeerLciHeaderForwarded=false;
        for (LciHeader lciHeader : lciHeaders) {
             lcScope = lciHeader.getLcScope();
            if(lcScope == null || lcScope.size() < 1) {
                continue;
            }
            Map.Entry<String, String> entry = lcScope.entrySet().stream().findFirst().get();
            lcScopeKey = entry.getKey();
            lciheader = lciHeader.getRcvHeaderValue();
            if (!lcScopeKey.equals(CommonConstants.LCI_app_FQDN) && !lcScopeKey.equals(CommonConstants.LCI_SEPP_FQDN)) {
                headers.add(CommonConstants.LCI_HEADER_NAME, lciheader);

            }
        }

        logger.debug("OUT: LciUtility::updateLciHeader()");
    }

    public static void updatelciHeaders(HttpHeaders httpHeaders, StreamInfo streamInfo,
            LciConfiguration lciConfiguration, SutLciCacheMgr sutLciCacheMgr) {

        if (logger.isDebugEnabled()) {
            logger.debug("IN: LciUtility::updatelciHeaders() : IsRemoteappSelected : {}, TargetPlmnType() : {}",
                    streamInfo.getIsRemoteappSelected(), streamInfo.getTargetPlmnType());
        }
        if (lciConfiguration.isLciFeatureEnabled()) {
            logger.debug("LciUtility::updatelciHeaders(). Lci feature is enabled so handling the lci response headers");
            //app-C handling - this condition will true only for sepp-C
            if (streamInfo.getIsRemoteappSelected() || streamInfo.getTargetPlmnType() == TargetPlmnType.TPT_INTER_PLMN) {
                LciUtility.updateLciHeader(streamInfo, httpHeaders, Event.Response);
                if (logger.isDebugEnabled()) {
                    logger.debug("LciUtility::updatelciHeaders() LciFeature is Enabled : headrrs :{}", httpHeaders);
                }
            }
            //app-P handling - this condition will true only for sepp-p
            else if (streamInfo.getIsReceivedInterappMessage() || streamInfo.isMessageReceivedFromSepp()) {
                //do nothing
                logger.debug("lci headers is not required to update");
            }
            else if (lciConfiguration.isRelayPeerLci() == false) {
                logger.debug("lci relay flag is false ... so removing all lci headers from response");
                httpHeaders.remove(CommonConstants.LCI_HEADER_NAME);
            }

            if (Objects.nonNull(httpHeaders.getFirst(CommonConstants.LCI_HEADER_NAME))) {
                logger.debug("LciUtility::updatelciHeaders(). Pegging the nf_lci_tx header towards consumer");
            }
        }
        populateSutLciForConsumer(streamInfo, httpHeaders, sutLciCacheMgr);

        if (logger.isDebugEnabled()) {
            logger.debug("OUT: LciUtility::updatelciHeaders() : headers: {}", httpHeaders);
        }
    }

    public static void populateSutLciForConsumer(StreamInfo streamInfo, HttpHeaders httpHeaders,
            SutLciCacheMgr sutLciCacheMgr) {

        logger.debug("IN: LciUtility::populateSutLciForConsumer()");

        sutLciCacheMgr.populateLciHeaderForConsumer(streamInfo);
        LciHeader lciHeader = streamInfo.getSutLciForConsumer();
        if (lciHeader == null) {
            logger.debug("OUT: LciUtility::populateSutLciForConsumer() - null");
            return;
        }

        String lciHeaderStr = LciHeader.encode(lciHeader);
        if (StringUtils.isEmpty(lciHeaderStr))  {
            logger.debug("OUT: LciUtility::populateSutLciForConsumer() - empty");
            return;
        }

        httpHeaders.add(CommonConstants.LCI_HEADER_NAME,lciHeaderStr);

        if (logger.isDebugEnabled()) {
            logger.debug("OUT: LciUtility::populateSutLciForConsumer() : lciHeaderStr: {}", lciHeaderStr);
        }
    }

}

I am updating log level dynamically and log controller with below code reference.

Configurator.setLevel("com.comp.cgbu.cne", Level.toLevel(loggingLevels.getAppLogLevel()));  --> org.apache.logging.log4j.core.config.Configurator#setLevel(java.lang.String, org.apache.logging.log4j.Level)

private void updateFilter(int rate, String filterNewLoglevel) {
        LoggerContext ctx = (LoggerContext) LogManager.getContext(false);
        Configuration config = ctx.getConfiguration();
        LoggerConfig loggerConfig = config.getLoggerConfig(LogManager.ROOT_LOGGER_NAME);

        Filter filter = loggerConfig.getFilter();

        if (logger.isLogLevelEnabled(LOGLEVEL.DEBUG)) {
            logger.construct("logMsg", "updateFilter .");
            logger.construct("rate: ", rate);
            logger.construct("filterLoglevel: ", filterNewLoglevel);
            logger.submit();
        }

        // Remove Filter:
        if (filter != null) {
            if (logger.isLogLevelEnabled(LOGLEVEL.DEBUG)) {
                logger.construct("logMsg",
                        "filter to be removed.");
                logger.construct("filter: ", filter);
                logger.submit();
            }
            // in case of more than one filter, remove the burst filter only
            if (filter instanceof CompositeFilter) {
                CompositeFilter compositeFilter = (CompositeFilter) filter;
                compositeFilter.iterator().forEachRemaining(ftr -> {
                    if (ftr instanceof BurstFilter) {
                        loggerConfig.removeFilter(ftr);
                    }
                });
            } else {
                 //remove only if the type is burst filter
                if (filter instanceof BurstFilter) {
                    loggerConfig.removeFilter(filter);
                }
            }

        } 

        //Adding filter
        addFilter(loggerConfig, rate, filterNewLoglevel);
                if ( !filterNewLoglevel.equals(Level.OFF.toString()) ) {

            BurstFilter burstFilter = BurstFilter.newBuilder().setLevel(Level.toLevel(filterNewLoglevel)).setRate(rate).setMaxBurst(rate)
                    .setOnMatch(Result.ACCEPT).setOnMismatch(Result.DENY).build();
            loggerConfig.addFilter(burstFilter);

            if (logger.isLogLevelEnabled(LOGLEVEL.DEBUG)) {
                logger.construct("logMsg", "BrustFilter added.");
                logger.construct("BrustFilter: ", burstFilter);
                logger.submit();
            }
        } else {
            if (logger.isLogLevelEnabled(LOGLEVEL.DEBUG)) {
                logger.construct("logMsg",
                        "Level set as OFF, BrustFilter not added.");
                logger.submit();
            }
        }

        //updating loggers
        ctx.updateLoggers(config);
    }

Kindly suggest how we can to prevent this behaviour.

Regards, Mohammad.

[ppkarwasz]

Hi @MohammadNC,

Can you explain what are you trying to achieve? Which level do you set to DEBUG?

Your programmatic configuration seems equivalent to:

<Loggers>
  <Root level="INFO">
    <BurstFilter onMatch="ACCEPT onMismatch="DENY" level="${filterNewLogLevel|"/>
    <AppenderRef ref="console"/>
  </Root>
  <Logger name="com.oracle.cgbu.cne"
          level="${appLevel}/>
</Loggers>

What values of ${filterNewLogLevel} and ${appLevel} are you using?

[MohammadNC]

Hi @ppkarwasz ,

Thank you for your response, please check below requested details.

In my application, there is a feature to dynamically update log levels and control the log rate. When we update the log level at the application level, all Java classes in the application adopt this new log level.

Here's my issue: When I set the log level to "INFO", "WARN", or "ERROR" at the application level, all classes correctly log messages at the respective levels. However, there is one specific class, LciUtility.java, that continues to print DEBUG level logs even when the application log level is set to INFO, WARN, or ERROR.

Note: The LciUtility class is located within the same application package as the other classes.

Additional details: appLevel refers to the application-level log setting. filterNewLogLevel specifies the log level at which log rate control needs to be applied.

Kindly check this info and provide suggestions how to resolve this issue.

[ppkarwasz]

Hi @MohammadNC,

Here's my issue: When I set the log level to "INFO", "WARN", or "ERROR" at the application level, all classes correctly log messages at the respective levels. However, there is one specific class, LciUtility.java, that continues to print DEBUG level logs even when the application log level is set to INFO, WARN, or ERROR.

Note: The LciUtility class is located within the same application package as the other classes.

There is nothing in LciUtility that stands out. My guess is that you might have a <Logger> configuration that is more specific that "com.comp.cgbu.cne" (e.g. com.comp.cgbu.cne.Lciutility). If this is the case, modifications of the log level for "com.comp.cgbu.cne" do not propagate to the logger of the LciUtility class.

Since local JMX is enabled in Log4j Core up to 2.23.1, the easiest way to verify it is to start jconsole and attach it to the running application. The MBean's for all logging contexts should be available in the org.apache.logging.log4j2 JMX domain.