How-To: Enable and Modify Logging Level in ForgeOps for AM

Hi all, I would like to start by saying this article is as much for me as it is for you. It contains notes on how to do some things.

The ForgeOps team has been worked quite a lot on providing different deployment strategies for ForgeOps. I would like to particularly like to thank Lee Baines-Dark for looking into this issue and implementing the changes required.

Please note the forgeops repository is in continuous development and might have changed since this post was written. These steps were tested on branch 7.3-20230609.

Logging in a Kubernetes environment

Logging is enabled by default to some level in all of our products.

Logs inside of a pod can be accessed by running the kubectl logs <podName> command.
Use kubectl get pods command to obtain the pod name that is needed. An example output of the command looks like this:

NAME                           READY   STATUS    RESTARTS   AGE
admin-ui-6645d49486-b8cwk      1/1     Running   0          147m
am-7b5bfb67bd-td75j            1/1     Running   0          84m
ds-idrepo-0                    1/1     Running   0          20h
end-user-ui-74bd5fc9c4-22znb   1/1     Running   0          64m
idm-8548776488-8txzl           1/1     Running   0          84m
login-ui-74c7d4476d-6r9cz      1/1     Running   0          84m

An example command that fetches the logs for AM in this CDK deployment, would be kubectl logs am-7b5bfb67bd-td75j. CDM deployments of ForgeOps will likely have more than one AM pod.

Since kubectl logs needs to be run on each pod, it is very difficult to monitor the logs of all the pods in an environment at once. Therefore, Kubernetes logging does not provide a complete logging solution and further options need to be explored for production deployment.

They way Kubernetes captures logs is via a container’s standard output (stdout) and standard error (stderr) streams in a running pod. ForgeRock products provide handlers for directing this output to the pod filesystem. These are the options that will be used to modify the logging level.

Logging Limitations

The stdout and stderr logs are stored in a file called log-file.log located within a cluster node and not on a pod’s filesystem. Therefore logs do not increase disk space a pod needs. The disk space of the cluster node that hosts the pod is utilised instead.

Log files are rotated once they exceed 10MB or once a day. Kubernetes maintains 5 log files. Whenever the kubectl logs command is run, it fetches the last log file only.

The log files can also be accessed by connecting to the cluster node directly. If the node uses systemd, the logs can be found using journald, by running the journalctl command.

If the container within a pod is somehow terminated, the logs are retained.

If a pod contains no containers, it is terminated.

If the pod hosting the container is terminated, the logs are lost.

If the node hosting the pod is somehow terminated, the pod is also automatically terminated and restarted where there is compute resources are available.

ForgeRock recommends that a ForgeOps administrator implements a log aggregator to gather logs from many pods, and that logs are retained after incidents and outages.

Modifying logging level for CDK only via example.com/am/Logback.jsp

This solution will not survive the termination of a pod. It is not be applicable for a CDM deployment due to the settings not being replicated across pods.

More information on this utility is available in the official AM documentation.

The above URL opens an interface that looks like this :

Once modified and set to TRACE, a kubectl logs command returns the appropriate output:

{"timestamp":"2023-06-20T11:26:44.405Z","level":"TRACE","thread":"LDAP SDK Default Scheduler","logger":"org.forgerock.opendj.io.Asn1Writer","message":"WRITE ASN.1 NULL(type=0x42, length=0)","context":"default","transactionId":null}
{"timestamp":"2023-06-20T11:26:44.405Z","level":"TRACE","thread":"LDAP SDK Default Scheduler","logger":"org.forgerock.opendj.io.Asn1Writer","message":"WRITE ASN.1 END SEQUENCE(length=5)","context":"default","transactionId":null}
{"timestamp":"2023-06-20T11:26:44.445Z","level":"TRACE","thread":"DirectoryWatcher-0","mdc":{"transactionId":"f9db32b9-814b-41eb-b8bc-38713935a4f6-0"},"logger":"org.forgerock.util.DirectoryWatcher","message":"No filesystem events to process","context":"default","transactionId":"f9db32b9-814b-41eb-b8bc-38713935a4f6-0"}

Modifying the logging level by temporarily modifying the related am-logback configmap.

This action is not permanent and will be undone by reapplication and redeployment of ForgeOps. It is however useful for temporarily increasing the visibility into the logs and can be just as easily undone.

To ensure that the required resources are available and the version of 7.3-20230609 is used, run the kubectl get configmaps, the result of which should show as follows:

am-logback               1      3h11m
amster-files             2      22h
amster-retain            1      22h
dev-utils                6      22h
idm                      10     22h
idm-logging-properties   1      22h
kube-root-ca.crt         1      20d
platform-config          24     22h

The configmap of interest is am-logback
To carry out the edit, please run:

$ kubectl edit configmap am-logback

This will open the configmap in vi :

# Please edit the object below. Lines beginning with a '#' will be ignored,
# and an empty file will abort the edit. If an error occurs while saving this file will be
# reopened with the relevant failures.
#
apiVersion: v1
data:
  logback.xml: |
    <!--
        ~ Copyright 2022-2023 ForgeRock AS. All Rights Reserved
        ~
        ~ Use of this code requires a commercial software license with ForgeRock AS.
        ~ or with one of its affiliates. All use shall be exclusively subject
        ~ to such license between the licensee and ForgeRock AS.
        -->

    <configuration scan="true" scanPeriod="30 seconds">

        <appender name="JSON" class="ch.qos.logback.core.ConsoleAppender">
            <filter class="com.forgerock.idc.LogFilter" />
            <encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
                <layout class="org.forgerock.openam.logback.JsonLayout">
                    <timestampFormat>yyyy-MM-dd'T'HH:mm:ss.SSSX</timestampFormat>
                    <timestampFormatTimezoneId>Etc/UTC</timestampFormatTimezoneId>
                    <jsonFormatter class="ch.qos.logback.contrib.jackson.JacksonJsonFormatter"/>
                    <appendLineSeparator>true</appendLineSeparator>
                </layout>
            </encoder>
        </appender>

        <!-- The following sets the default logging level -->
        <root level="WARN">
            <appender-ref ref="JSON" />
        </root>

        <!-- The following section sets logging to INFO level & above in certain packages/classes to filter out noise -->
        <!-- individual classes -->
        <logger name="com.sun.identity.authentication.client.AuthClientUtils" level="INFO" />

        <!-- The following section sets logging to WARN level & above in certain packages/classes to filter out noise -->
        <!-- packages -->
        <logger name="oauth2" level="WARN" />
        <logger name="org.apache.http" level="WARN" />
        <logger name="com.iplanet.dpro.session" level="WARN" />
        <logger name="com.sun.identity.sm" level="WARN" />
        <logger name="org.forgerock.am.health.ReadinessCheckEndpoint" level="WARN" />
        <logger name="org.forgerock.openam.core.rest.session" level="WARN" />
        <logger name="org.forgerock.openam.core.rest.sms" level="WARN" />
        <logger name="org.forgerock.openam.core.sms" level="WARN" />
        <logger name="org.forgerock.openam.session" level="WARN" />
...

Please note that this file is queried every 30 seconds as stated in this line <configuration scan="true" scanPeriod="30 seconds"> . The second line that is important for this edit is the log level <root level="WARN"> . By default this is set to WARN, this level has a fuller description in the official AM Documentation.

To change the logging level change, this variable needs to be changed. For the purposes of this demonstration it will altered to TRACE, as this is a very verbose output.

The changes will take effect in around 2mins depending on the responsiveness of the cluster and timer variation.

The desired output can be verified by running kubectl logs <nameofAmPod>:

{"timestamp":"2023-06-20T13:08:52.476Z","level":"TRACE","thread":"LDAP SDK Default AsyncRx I/O Thread (1)","logger":"org.forgerock.opendj.io.Asn1Reader","message":"READ ASN.1 START SEQUENCE(type=0x65, length=7)","context":"default","transactionId":null}
{"timestamp":"2023-06-20T13:08:52.476Z","level":"TRACE","thread":"LDAP SDK Default AsyncRx I/O Thread (1)","logger":"org.forgerock.opendj.io.Asn1Reader","message":"READ ASN.1 INTEGER(type=0xa, length=1, value=0)","context":"default","transactionId":null}
{"timestamp":"2023-06-20T13:08:52.476Z","level":"TRACE","thread":"LDAP SDK Default AsyncRx I/O Thread (1)","logger":"org.forgerock.opendj.io.Asn1Reader","message":"READ ASN.1 END SEQUENCE","context":"default","transactionId":null}
{"timestamp":"2023-06-20T13:08:52.476Z","level":"TRACE","thread":"LDAP SDK Default AsyncRx I/O Thread (1)","logger":"org.forgerock.opendj.io.LdapReader","message":"DECODE LDAP SEARCH RESULT(messageID=4447, result=Result(resultCode=Success, matchedDn=, diagnosticMessage=, referrals=[], controls=[]))","context":"default","transactionId":null}
{"timestamp":"2023-06-20T13:08:52.476Z","level":"TRACE","thread":"LDAP SDK Default AsyncRx I/O Thread (1)","logger":"org.forgerock.opendj.io.Asn1Reader","message":"READ ASN.1 END SEQUENCE","context":"default","transactionId":null}

To return it to normal, simply repeat these steps with the variable set as WARN instead of TRACE

Modifying the logging level by permanently modifying the Kubernetes environment and setting a new default logging level

This action is a permanent modification to the deployment.

This is done by modifying the kustomize/base folder to use a new default state for the application.

To begin, the logback.xml file will need to be modified. It is located in the /path/to/forgeops/kustomize/base/am-cdk/config folder. An easy way to do so is to use the following command to run vim:

$ vim /path/to/fogeops/kustomize/base/am-cdk/config/logback.xml

Once opened the file looks like this:

<!--
    ~ Copyright 2022-2023 ForgeRock AS. All Rights Reserved
    ~
    ~ Use of this code requires a commercial software license with ForgeRock AS.
    ~ or with one of its affiliates. All use shall be exclusively subject
    ~ to such license between the licensee and ForgeRock AS.
    -->

<configuration scan="true" scanPeriod="30 seconds">

    <appender name="JSON" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="com.forgerock.idc.LogFilter" />
        <encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
            <layout class="org.forgerock.openam.logback.JsonLayout">
                <timestampFormat>yyyy-MM-dd'T'HH:mm:ss.SSSX</timestampFormat>
                <timestampFormatTimezoneId>Etc/UTC</timestampFormatTimezoneId>
                <jsonFormatter class="ch.qos.logback.contrib.jackson.JacksonJsonFormatter"/>
                <appendLineSeparator>true</appendLineSeparator>
            </layout>
        </encoder>
    </appender>

    <!-- The following sets the default logging level -->
    <root level="WARN">
        <appender-ref ref="JSON" />
    </root>

    <!-- The following section sets logging to INFO level & above in certain packages/classes to filter out noise -->
    <!-- individual classes -->
    <logger name="com.sun.identity.authentication.client.AuthClientUtils" level="INFO" />

    <!-- The following section sets logging to WARN level & above in certain packages/classes to filter out noise -->
    <!-- packages -->
    <logger name="oauth2" level="WARN" />
    <logger name="org.apache.http" level="WARN" />
    <logger name="com.iplanet.dpro.session" level="WARN" />
    <logger name="com.sun.identity.sm" level="WARN" />
    <logger name="org.forgerock.am.health.ReadinessCheckEndpoint" level="WARN" />
    <logger name="org.forgerock.openam.core.rest.session" level="WARN" />
    <logger name="org.forgerock.openam.core.rest.sms" level="WARN" />
    <logger name="org.forgerock.openam.core.sms" level="WARN" />
    <logger name="org.forgerock.openam.session" level="WARN" />
    <logger name="org.forgerock.openam.sm" level="WARN" />
    <!-- individual classes -->
    <logger name="com.iplanet.services.naming.WebtopNaming" level="WARN" />
    <logger name="com.iplanet.sso.providers.dpro.SSOProviderImpl" level="WARN" />
...

To modify the logging level, <root level="WARN"> sets the global logging level. For the purposes of this article we will modify this to <root level="TRACE"> and save the file.

To apply the changes to an existing cluster run:

$ bin/forgeops install am --<size> --namespace <yourNamespace>

If the ForgeOps deployment is initialised for the first the first time on a new cluster the --fqdn <yourFqdn> flag will need to be added.

The desired output can be verified by running kubectl logs <nameofAmPod>:

{"timestamp":"2023-06-21T11:05:02.662Z","level":"TRACE","thread":"DirectoryWatcher-0","mdc":{"transactionId":"01234783-47ab-4f87-939e-ca844323b284-0"},"logger":"org.forgerock.util.DirectoryWatcher","message":"No filesystem events to process","context":"default","transactionId":"01234783-47ab-4f87-939e-ca844323b284-0"}
{"timestamp":"2023-06-21T11:05:03.662Z","level":"TRACE","thread":"DirectoryWatcher-0","mdc":{"transactionId":"01234783-47ab-4f87-939e-ca844323b284-0"},"logger":"org.forgerock.util.DirectoryWatcher","message":"No filesystem events to process","context":"default","transactionId":"01234783-47ab-4f87-939e-ca844323b284-0"}
10.28.5.1 - - [21/Jun/2023:11:04:59 +0000] "GET /am/json/health/ready HTTP/1.1" 200 - 5ms
{"timestamp":"2023-06-21T11:05:04.662Z","level":"TRACE","thread":"DirectoryWatcher-0","mdc":{"transactionId":"01234783-47ab-4f87-939e-ca844323b284-0"},"logger":"org.forgerock.util.DirectoryWatcher","message":"No filesystem events to process","context":"default","transactionId":"01234783-47ab-4f87-939e-ca844323b284-0"}

To return it to normal, simply repeat these steps with the variable set as WARN instead of TRACE

Conclusion

There are three methods for enabling logging in AM for ForgeOps:

  • Using the logback.jsp page
  • Temporarily modifying the am-logback configmap
  • Permanently altering ForgeOps to set a new default logging level

The final piece of the puzzle would be the implementation of an external log ingester. By default, Google Kubernetes Engine provides logs in the form of Google Cloud Monitoring and Logging (Formerly Stackdriver). Enabling first-party tools or using third-party tools is recommended for Azure and AWS.

5 Likes