JDK-8272877 : Java VM warning messages are not printed using the vfprintf hook
  • Type: Bug
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 8u301
  • Priority: P4
  • Status: Closed
  • Resolution: Incomplete
  • OS: generic
  • CPU: generic
  • Submitted: 2021-08-04
  • Updated: 2025-06-22
  • Resolved: 2021-08-24
Related Reports
Relates :  
Description
ADDITIONAL SYSTEM INFORMATION :
OS: Red Hat Enterprise Linux 8
JDK: JDK 8 Update 301, JDK 11.0.12, JDK 16.0.2

I have reproduced this issue in the above environment.
But I think this issue probably will occur on any OS.

A DESCRIPTION OF THE PROBLEM :
JNI_CreateJavaVM can create a Java VM with a vfprintf hook by specifying vfprintf option.
https://docs.oracle.com/javase/8/docs/technotes/guides/jni/spec/invocation.html#JNI_CreateJavaVM

But Java VM warning messages such as the following are not comletely printed using the vfprintf hook.

Java HotSpot(TM) 64-Bit Server VM warning: <message>

"Java HotSpot(TM) 64-Bit Server VM warning: " (with no newline) is printed using the vfprintf hook.
But the rest part of the message (with a newline) is printed to the stderr.

[example]
Specify the following Java VM options to cause a Java VM warning message.

-XX:+UnlockDiagnosticVMOptions -XX:+LogCompilation -XX:LogFile=not_existing_directory/compilation.log
(`not_existing_directory` is a not-existing directory.)

The above Java VM options cause the following warning message.

Java HotSpot(TM) 64-Bit Server VM warning: Cannot open file not_existing_directory/compilation.log due to No such file or directory

If a vfprintf hook is not specified when creating a Java VM, the whole message is printed to the stderr.
If a vfprintf hook is specified when creating a Java VM, "Java HotSpot(TM) 64-Bit Server VM warning: " (with no newline) is printed using the vfprintf hook and "Cannot open file not_existing_directory/compilation.log due to No such file or directory" (with a newline) is printed to the stderr.

I think the cause of this issue is the following warning function.
https://github.com/openjdk/jdk/blob/master/src/hotspot/share/utilities/debug.cpp#L116

"<Java VM name> warning: " is printed using the jio_fprintf function.
And the rest part of the message is printed using the vfprintf function and the fputc function.
The jio_fprintf function uses the vfprintf hook to print messages if the vfprintf hook is specified.
But the vfprintf function does not using the vfprintf hook.

I think the rest part of the message should also be printed using the jio_fprintf function or the jio_vfprintf function instead of the vfprintf function or the fputc function.

STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
1. Compile create_jvm.c (the attached source code)
JDK 8
> gcc -Wall -O3 -I $JAVA_HOME/include -I $JAVA_HOME/include/linux -L $JAVA_HOME/jre/lib/amd64/server -l jvm -o create_jvm create_jvm.c
JDK 11 or JDK 16
> gcc -Wall -O3 -I $JAVA_HOME/include -I $JAVA_HOME/include/linux -L $JAVA_HOME/lib/server -l jvm -o create_jvm create_jvm.c

2. Run the compiled program
(The first argument is the log file name used by the vfptintf hook.)
JDK 8
> export LD_LIBRARY_PATH=$JAVA_HOME/jre/lib/amd64/server
> ./create_jvm.c jvm.log
JDK 11 or JDK 16
> export LD_LIBRARY_PATH=$JAVA_HOME/lib/server
> ./create_jvm.c jvm.log


EXPECTED VERSUS ACTUAL BEHAVIOR :
EXPECTED -
The whole of the following Java VM warning message is printed to the jvm.log.

Java HotSpot(TM) 64-Bit Server VM warning: Cannot open file not_existing_directory/compilation.log due to No such file or directory

ACTUAL -
The following message (with no newline) is printed to the jvm.log.

Java HotSpot(TM) 64-Bit Server VM warning: 

And the following message is printed to the stderr.

Cannot open file not_existing_directory/compilation.log due to No such file or directory

[note]
The content of the jvm.log file is the following.

Java HotSpot(TM) 64-Bit Server VM warning: Warning:  Cannot open log file: not_existing_directory/compilation.log
Warning:  Forcing option -XX:LogFile=/tmp/compilation.log

"Java HotSpot(TM) 64-Bit Server VM warning: " (with no newline) is printed using the jio_fprintf function at the warning function.
The following messages are printed using the jio_print function or the jio_printf function at the defaultStream::open_file function.

Warning:  Cannot open log file: not_existing_directory/compilation.log
Warning:  Forcing option -XX:LogFile=/tmp/compilation.log

"Java HotSpot(TM) 64-Bit Server VM warning: " is not finished a newline.
So, the next message "Warning:  Cannot open log file: not_existing_directory/compilation.log" is printed the same line.


---------- BEGIN SOURCE ----------
/* create_jvm.c */
#include <stdio.h>
#include <stdlib.h>
#include <jni.h>

static jint (JNICALL my_vfprintf)(FILE *, const char *, va_list);

static FILE *log_file;

int main(int argc, char *argv[]) {
  JavaVM *vm;
  JNIEnv *env;
  JavaVMInitArgs vm_args;
  JavaVMOption options[4];

  vm_args.version = JNI_VERSION_1_8;
  vm_args.options = options;
  vm_args.nOptions = 4;
  vm_args.ignoreUnrecognized = JNI_FALSE;

  options[0].optionString = "vfprintf";
  options[0].extraInfo = (void *) my_vfprintf;
  options[1].optionString = "-XX:+UnlockDiagnosticVMOptions";
  options[2].optionString = "-XX:+LogCompilation";
  options[3].optionString = "-XX:LogFile=not_existing_directory/compilation.log";

  fprintf(stdout, "Start\n");

  if (argc <= 1) {
    fprintf(stderr, "Usage: %s <log_file>\n", argv[0]);
    exit(1);
  }

  if ((log_file = fopen(argv[1], "w")) == NULL) {
    fprintf(stderr, "Failed to open file\n");
    exit(1);
  }

  if (JNI_CreateJavaVM(&vm, (void **) &env, &vm_args) != JNI_OK) {
    fprintf(stderr, "Failed to create Java VM\n");
    fclose(log_file);
    exit(1);
  }

  if ((*vm)->DestroyJavaVM(vm) != JNI_OK) {
    fprintf(stderr, "Failed to destroy Java VM\n");
    fclose(log_file);
    exit(1);
  }

  fclose(log_file);

  fprintf(stdout, "Done\n");
  return 0;
}

jint (JNICALL my_vfprintf)(FILE *fp, const char *format, va_list args) {
  return vfprintf(log_file, format, args);
}

---------- END SOURCE ----------

FREQUENCY : always



Comments
The JNI invocation vfprintf hook was apparently added to redirect messages produced when running under the Windows GUI: https://web.archive.org/web/20111229234347/http://java.sun.com/products/jdk/faq/jnifaq-old.html This was done with the early Windows reference implementation under JDK-4015550 and added to Hotspot later in Java 1.1 under JDK-4237806. There is no actual specification, that I can find, for exactly how it is supposed to work. Reading between the lines though the suggestion seems to be that output produced during JNI_CreateJavaVM should be redirected via the hook. The Sheng Liang "Java Native Interface: Programmer’s Guide and Specification" book does document it as: /* a hook for a function that redirects * all VM messages. */ jint (*vfprintf)(FILE *fp, const char *format, va_list args); but that is it. As noted in the bug report it is connected to the jio_vfprintf() function, but that in turn is only called from some specific areas, varying greatly depending on which JDK version you look at - so I don't think it has ever redirected "all" VM messages. In particular the warning() function that is the subject of this bug report does not use the jio_ interface at all in Java 7 and earlier, and only partially (and thus incorrectly) in Java 8. That partial use came in under JDK-7199082 and while there was a lengthy discussion about handling VM output, the existence of the vprintf hook was not even raised (which suggests noone even remembered it existed - myself included). It is worth noting that early on it was mentioned, without resolution, in the context of "-verbose" output, in the duplicate JDK-4498651. Finally, it is worth noting that the introduction of Unified Logging in the VM in 9: http://openjdk.java.net/jeps/158 should have rendered this API hook obsolete. That all said we could at least make the warning() function in JDK 8 use the jio_ interface consistently and thus direct the entire message to the same location. I would not suggest making any changes after JDK 8 but instead direct developers embedding the VM to use the -Xlog command-line flags via the invocation API.
24-08-2021