WLO 1.5.0 - Liberty InstantOn app can't start with .spec.serviceability in WebSphereLibertyApplication CR

[tam512]

Test on Azure Kubernetes Service (AKS) with storage class azurefile-premium . When having .spec.serviceability in WebSphereLibertyApplication CR, Liberty InstantOn app can start okay if using WLO 1.4.4 but it fails to start with WLO 1.5.0

I have the following in the WebSphereLibertyApplication CR and deploy app with WLO 1.5.0

spec:
  serviceability:
    size: 1G
    storageClassName: azurefile-premium

the application failed to start without any message or error in the log

% oc -n ebuy-wlk-ubi9-j17 get po
NAME                  READY   STATUS             RESTARTS      AGE
ebuy-wlk-ubi9-j17-0   0/1     CrashLoopBackOff   2 (20s ago)   56s

% oc -n ebuy-wlk-ubi9-j17 logs ebuy-wlk-ubi9-j17-0  --previous
Found mounted TLS certificates, generating keystore
Found mounted TLS CA certificate, adding to truststore

% oc -n ebuy-wlk-ubi9-j17 get pvc 
NAME                               STATUS   VOLUME                                     CAPACITY   ACCESS MODES   STORAGECLASS        VOLUMEATTRIBUTESCLASS   AGE
ebuy-wlk-ubi9-j17-serviceability   Bound    pvc-0c53a767-6f3d-4725-be69-7a397fe4e89f   1G         RWX            azurefile-premium   <unset>                 53s

• The app can start ok without resume from instantOn checkpoint by setting the env variable CRIU_RESTORE_DISABLE_RECOVERY="false" as following

spec:
  env:
  - name: CRIU_RESTORE_DISABLE_RECOVERY
    value: "false"

Below is the AKS cluster nodes info

% oc get nodes -o wide
NAME                              STATUS   ROLES    AGE   VERSION   INTERNAL-IP   EXTERNAL-IP   OS-IMAGE             KERNEL-VERSION      CONTAINER-RUNTIME
aks-default-12122487-vmss000000   Ready    <none>   17h   v1.33.2   10.224.0.4    <none>        Ubuntu 22.04.5 LTS   5.15.0-1092-azure   containerd://1.7.28-1

This problem was opened in 32960 but has narrowed down to operator issue.

[leochr]

Liberty Operator 1.5.0 included serviceability-related changes to the output locations of logs/traces. Perhaps that impacts InstantOn. I am not sure why. But hopefully, the information below on the Operator changes is helpful to understand the reason for the InstantOn failure and how to resolve it:

• When .spec.serviceability is enabled, the server logs are output to the pod-specific logs folder within the serviceability directory (i.e. /serviceability/my_namespace/my_pod_name/logs) from the initial server start (instead of /logs). Liberty env LOG_DIR is set to this location. This keeps the server logs location consistent regardless of whether tracing (via WebSphereLibertyTrace) is enabled or not. Previously (with Liberty Operator 1.4.4), the logs were output to /logs at server startup, then switched to the serviceability location for the pod when trace was enabled and then switched back to /logs once trace was disabled, which was not only inconsistent, but also split up the logs.
• A new symlink /liberty/logs is added in 25.0.0.10 container images. It’ll link to the pod's serviceability log directory (/serviceability/my_namespace/my_pod_name/logs) when serviceability is enabled; otherwise, it’ll link to /logs. This is to allow a consistent way to refer to the logs location. LOG_DIR is also set to /liberty/logs at the container level.

[tjwatson]

Can you point to issues and or PRs related to this change?

[leochr]

This is the primary issue: OpenLiberty/open-liberty-operator#677

Liberty Container PRs for 25.0.0.10+:

• Add runtime support for writing /logs to a /serviceability directory OpenLiberty/ci.docker#607
• Add runtime support for writing /logs to a /serviceability directory ci.docker#664

Operator PRs:

• Write Javacores to the /serviceability pod directory #794
• Write Javacores to the /serviceability pod directory OpenLiberty/open-liberty-operator#766

[leochr]

The main points to note here:

• /logs can't be assumed to be the logs directory. Liberty container images, till now, set LOG_DIR to /logs, but it's something users could also have overridden to something else.
• Liberty Operator 1.5.0+ sets LOG_DIR to the pod's serviceability directory (/serviceability/my_namespace/my_pod_name/logs) when .spec.serviceability is enabled.
• LOG_DIR would be set to /liberty/logs at the container level in 25.0.0.10+ by default, which would be a symlink to /logs, but when serviceability is enabled, /liberty/logs would be symlinked to the pod's serviceability directory (/serviceability/my_namespace/my_pod_name/logs).
• Hence, LOG_DIR and/or /liberty/logs should be used to reference the log directory

[leochr]

@tjwatson I just noticed that checkpoint.sh refers to /logs. Should they also include the /liberty/logs symlink? Would that resolve this issue?

echo "Performing checkpoint --at=$1"
/opt/ibm/wlp/bin/server checkpoint defaultServer --at=$1

rc=$?
if [ $rc -eq 0 ]; then
    # Find all directories in logs/ and output/ that the current user has read/write/execute permissions for
    # and give the same permissions to the group.
    find -L /logs /output -type d -readable -writable -executable -exec chmod g+rwx {} \;

    # Find all files in logs/ and output/ that the current user has read/write permissions for
    # and give the same permissions to the group.
    find -L /logs /output -type f -readable -writable -exec chmod g+rw {} \;
fi

[leochr]

FYI, further discussion: https://ibm-cloud.slack.com/archives/C03MR7EC3NG/p1759162105271909?thread_ts=1758733279.912129&cid=C03MR7EC3NG

[kabicin]

Hello @leochr and @tjwatson, the following examples may help to understand what is happening with InstantOn using WLO 1.5.0. As you may know, the problem happens when changing LOG_DIR between the time of checkpoint and restore, which is an issue separate from the operator. The operator is setting LOG_DIR at runtime which is why we see this issue pop up. All three scenarios affecting InstantOn can be recreated with just the Dockerfiles and commands below. Luckily, the golden path (never changing LOG_DIR) still allows checkpoint/restore to succeed and the issue can only be reproduced in the case where LOG_DIR is changed (also when a user enables the Liberty operator serviceability feature). Please see the examples below for more info:

1. Restore fails or does not register when LOG_DIR changes between checkpoint and restore. For example, checkpoint with LOG_DIR=/liberty/logs and restore with LOG_DIR=/logs2 will lead to no restore.

Dockerfile

FROM stg.icr.io/cp/olc/open-liberty-vnext:25.0.0.10-kernel-slim-java21-openj9-ubi-minimal

COPY --chown=1001:0 server.xml /config/

USER 0
RUN mkdir -p /logs2 && chmod -R g+rw /logs2 && chown -R 1001:0 /logs2
USER 1001


RUN checkpoint.sh beforeAppStart

ENV LOG_DIR=/logs2

Build

docker build --platform=linux/amd64 --cap-add=CHECKPOINT_RESTORE --cap-add=SYS_PTRACE --cap-add=SETPCAP --security-opt seccomp=unconfined -t test1 .
docker run --privileged test1

Output

WARNING: Unknown module: jdk.management.agent specified to --add-exports
WARNING: Unknown module: jdk.attach specified to --add-exports
Launching defaultServer (Open Liberty 25.0.0.10/wlp-1.0.106.cl251020250923-1355) on Eclipse OpenJ9 VM, version 21.0.8+9-LTS (en_US)
[AUDIT   ] CWWKE0001I: The server defaultServer has been launched.
[AUDIT   ] CWWKG0093A: Processing configuration drop-ins resource: /opt/ol/wlp/usr/servers/defaultServer/configDropins/defaults/keystore.xml
[AUDIT   ] CWWKG0093A: Processing configuration drop-ins resource: /opt/ol/wlp/usr/servers/defaultServer/configDropins/defaults/open-default-port.xml
[ERROR   ] CWWKF0001E: A feature definition could not be found for transportsecurity-1.0
[ERROR   ] CWWKF0001E: A feature definition could not be found for servlet-4.0
[AUDIT   ] CWWKF0012I: The server installed the following features: [].
[AUDIT   ] CWWKF0011I: The defaultServer server is ready to run a smarter planet. The defaultServer server started in 1.290 seconds.

2. Restore has no problem when LOG_DIR does not change. For example, In this case LOG_DIR=/liberty/logs -> /logs is a symlink from /liberty/logs to /logs. With no changes the restore succeeds.

Dockerfile

FROM stg.icr.io/cp/olc/open-liberty-vnext:25.0.0.10-kernel-slim-java21-openj9-ubi-minimal

COPY --chown=1001:0 server.xml /config/

RUN checkpoint.sh beforeAppStart

Build

docker build --platform=linux/amd64 --cap-add=CHECKPOINT_RESTORE --cap-add=SYS_PTRACE --cap-add=SETPCAP --security-opt seccomp=unconfined -t test2 .
docker run --privileged test2

Output

[AUDIT   ] Launching defaultServer (Open Liberty 25.0.0.10/wlp-1.0.106.cl251020250923-1355) on Eclipse OpenJ9 VM, version 21.0.8+9-LTS (en_US)
[AUDIT   ] CWWKG0016I: Starting server configuration update.
[AUDIT   ] CWWKG0093A: Processing configuration drop-ins resource: /opt/ol/wlp/usr/servers/defaultServer/configDropins/defaults/keystore.xml
[AUDIT   ] CWWKG0093A: Processing configuration drop-ins resource: /opt/ol/wlp/usr/servers/defaultServer/configDropins/defaults/open-default-port.xml
[AUDIT   ] CWWKG0017I: The server configuration was successfully updated in 0.060 seconds.
[AUDIT   ] CWWKC0452I: The Liberty server process resumed operation from a checkpoint in 0.315 seconds.
[AUDIT   ] CWWKF0012I: The server installed the following features: [].
[AUDIT   ] CWWKF0011I: The defaultServer server is ready to run a smarter planet. The defaultServer server started in 0.329 seconds.

3. Restore outputs a blank screen when LOG_DIR does not change, but the underlying symlink is changed. For example, before checkpoint we have LOG_DIR=/liberty/logs -> /logs. Right before restore, if we recreate the symlink to become LOG_DIR=/liberty/logs -> /logs2 then the server will have no output to console.

Dockerfile

FROM stg.icr.io/cp/olc/open-liberty-vnext:25.0.0.10-kernel-slim-java21-openj9-ubi-minimal

COPY --chown=1001:0 server.xml /config/

USER 0
RUN mkdir -p /logs2 && chmod -R g+rw /logs2 && chown -R 1001:0 /logs2
USER 1001


RUN checkpoint.sh beforeAppStart

RUN rm /liberty/logs && ln -s /logs2 /liberty/logs

Build

docker build --platform=linux/amd64 --cap-add=CHECKPOINT_RESTORE --cap-add=SYS_PTRACE --cap-add=SETPCAP --security-opt seccomp=unconfined -t test3 .
docker run --privileged test3

Output

<blank screen>
^C
2025-10-01T19:45:05.544489Z: open pidfd: No such process

[tjwatson]

Took a while to untangle what is going on. There are two issues:

1. Liberty itself cannot handle LOG_DIR changing from checkpoint to restore. There are many places this is used very early in boot up of Liberty and it will be risky to try to change all the assumptions about this location changing or attempting to delay reading LOG_DIR until restore. We MUST read this ENV on startup to know where to put the logs during checkpoint. Once we read a value out of the ENV the Semeru InstantOn runtime will not let that value change from checkpoint to restore. To be able to change the value on restore Liberty must NOT read the value of the LOG_DIR ENV at all on the checkpoint side. This is not possible for the LOG_DIR value though. Any short-term solution must avoid changing the LOG_DIR value from its original /liberty/logs/

2. The server script code for capturing the console output from the restored process cannot handle when the symbolic link from /liberty/logs is changed. The base image sets LOG_DIR ENV value to /liberty/logs which initially is symbolically linked to /logs . When the checkpoint process initializes Liberty it it pipes the standard console out/err to $LOG_DIR/console.log. That ends up following the symbolic link from /liberty/logs -> /logs and then the pipe is set to /logs/console.log. Once that output is established it is part of the checkpointed process. The restored process will always pipe the console output to /logs/console.log regardless of the LOG_DIR ENV value or the symbolic link change from /liberty/logs. On the other hand the server script will use the value of LOG_DIR to determine where the console.log is so it can capture the output from the restored process (written to console.log) and display it for the container output. Since the symbolic link from /liberty/logs changes it ends up trying to read the console.log output from a different location than the one the restored process is writing to. Any short-term solution must have the server script somehow know the original canonical location of the console.log (not symbolic link location) which the checkpoint process uses and it must ready the output from there.

I think this is possible to fix, but will probably take changes server script to do the following:

1. Compute the real path to the console.log and LOG_DIR ENV used at checkpoint time. Store that information in the server workarea
2. On restore, be sure to restore the LOG_DIR ENV value to the original value before (and only for) restoring the checkpoint process.
3. On restore, read the console.log from the original location used during checkpoint.

Some possible improvements for the long-term:

1. Enhance Semeru/CRIU to allow the standard output pipe path to change for restore so that we read from the changed linked location on restore
2. Introduce a LOG_DIR_CHECKPOINT ENV that we only read on the checkpoint side for the log dir location. Never read the LOG_DIR value before checkpoint. Upon restore, ready the LOG_DIR value for the first time and detect if it has changed from the original LOG_DIR_CHECKPOINT value and apply the changes if necessary.