RFR: 8267926: AsyncLogGtest.java fails on assert with: decorator was not part of the decorator set specified at creation. [v3]

[Xin Liu]

On Tue, 1 Jun 2021 05:09:31 GMT, David Holmes <dholmes at openjdk.org> wrote:

>> Xin Liu has updated the pull request incrementally with one additional commit since the last revision:
>> 
>>   Increase reader's counter before creating LogDecoration.
>
> I put the latest patch through our tier 1-4 testing and it crashed in tier 3 on Linux-Aarch64:
> 
> #
> # A fatal error has been detected by the Java Runtime Environment:
> #
> #  SIGSEGV (0xb) at pc=0x0000ffff40820720, pid=3972473, tid=3972481
> #
> # JRE version: Java(TM) SE Runtime Environment (17.0) (fastdebug build 17-internal+0-LTS-2021-05-31-2211099.david.holmes.jdk-dev4.git)
> # Java VM: Java HotSpot(TM) 64-Bit Server VM (fastdebug 17-internal+0-LTS-2021-05-31-2211099.david.holmes.jdk-dev4.git, mixed mode, tiered, compressed oops, compressed class ptrs, g1 gc, linux-aarch64)
> # Problematic frame:
> # C  [libc.so.6+0x60720]  flockfile+0x0
> #
> # Core dump will be written. Default location: Core dumps may be processed with "/opt/core.sh %p" (or dumping to /opt/mach5/mesos/work_dir/slaves/a4f8fba9-f017-4328-b286-c66b6a97143d-S808/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/42993029-a18a-48c4-9a4d-108aee7b3811/runs/a38508fe-5d43-48ad-b70a-61f3e712fcd8/testoutput/test-support/jtreg_open_test_hotspot_jtreg_hotspot_misc/scratch/0/core.3972473)
> #
> # If you would like to submit a bug report, please visit:
> #   https://bugreport.java.com/bugreport/crash.jsp
> #
> 
> ---------------  S U M M A R Y ------------
> 
> Command Line: -XX:+ExecutingUnitTests -Xlog:async 
> 
> Host: AArch64, 6 cores, 46G, Oracle Linux Server release 8.3
> Time: Mon May 31 22:37:04 2021 UTC elapsed time: 3.758723 seconds (0d 0h 0m 3s)
> 
> ---------------  T H R E A D  ---------------
> 
> Current thread (0x0000aaadf32b1e10):  Thread "AsyncLog Thread" [stack: 0x0000fffefdaa0000,0x0000fffefdca0000] [id=3972481]
> 
> Stack: [0x0000fffefdaa0000,0x0000fffefdca0000],  sp=0x0000fffefdc9e510,  free space=2041k
> Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
> C  [libc.so.6+0x60720]  flockfile+0x0
> V  [libjvm.so+0x1508058]  LogFileOutput::write_blocking(LogDecorations const&, char const*)+0x38
> V  [libjvm.so+0x1502764]  AsyncLogWriter::run()+0x2c0
> V  [libjvm.so+0x1a49d08]  Thread::call_run()+0xf8
> V  [libjvm.so+0x1766f18]  thread_native_entry(Thread*)+0x108
> C  [libpthread.so.0+0x76e0]  start_thread+0x198

hi, @dholmes-ora , 

I have another guess. This crash sight could also be caused by log rotation!

Stack: [0x0000fffefdaa0000,0x0000fffefdca0000], sp=0x0000fffefdc9e510, free space=2041k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
C [libc.so.6+0x60720] flockfile+0x0
V [libjvm.so+0x1508058] LogFileOutput::write_blocking(LogDecorations const&, char const*)+0x38
V [libjvm.so+0x1502764] AsyncLogWriter::run()+0x2c0
V [libjvm.so+0x1a49d08] Thread::call_run()+0xf8
V [libjvm.so+0x1766f18] thread_native_entry(Thread*)+0x108
C [libpthread.so.0+0x76e0] start_thread+0x198


It's possible that `write_blocking` is waken up from _rotation_semaphore.wait(), and proceed with writing. 


int LogFileOutput::write_blocking(const LogDecorations& decorations, const char* msg) {
  _rotation_semaphore.wait();

  int written = LogFileStreamOutput::write(decorations, msg);
....
}


`rotate()` could fail at os::fopen() due to space or fnode limitation. It will leave _stream == NULL and make 
` LogFileStreamOutput::write(decorations, msg)` fail at flockfile(NULL). 


void LogFileOutput::rotate() {
...
  _stream = os::fopen(_file_name, FileOpenMode);
  if (_stream == NULL) {
    errstream->print_cr("Error opening log file '%s': %s",
                        _file_name, os::strerror(errno));
    return false;
  }


I don't know how to make it happen. The easiest way to verify my guess is to grep  'Error opening log file' if you still have those files. or you may try this revision. I remove AsyncLogGtest.java from problemlist. 

https://github.com/openjdk/jdk/pull/4257/commits/a52019d2e413398b97ed36463cd0d439f3caed4d

-------------

PR: https://git.openjdk.java.net/jdk/pull/4257