Uploaded image for project: 'JBoss Enterprise Application Platform'
  1. JBoss Enterprise Application Platform
  2. JBEAP-20056

[GSS](7.3.z) WFLY-13933 - access-log entries might become lost during the shutdown even if graceful timeout is specified

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Won't Do
    • Icon: Major Major
    • None
    • None
    • Undertow
    • None
    • Hide

      To reproduce this issue, you can use either of the following methods to emulate slow down before completing to write all access log entries. Then, trigger shutdown during the slowdown.

      • Use debugger to set thread-level breakpoint in Undertow's DefaultAccessLogReceiver#writeMessage() (or inside run())
      • Use byteman script to invoke Thread.sleep() in Undertow's DefaultAccessLogReceiver#writeMessage() (or inside run())
      RULE DefaultAccessLogReceiver_writeMessage
CLASS io.undertow.server.handlers.accesslog.DefaultAccessLogReceiver
METHOD writeMessage
AT ENTRY
IF TRUE
DO
  traceStack("-------------- io.undertow.server.handlers.accesslog.DefaultAccessLogReceiver#writeMessage() is invoked \n");
  Thread.sleep(10000L); // emulate slow down
ENDRULE

      Then, follow the steps:

      1. Send several requests to JBoss

      ab -n 10 -c 5 http://127.0.0.1:8080/

      2. Shutdown JBoss (the same result happens regardless of using graceful shutdown or not)

      ./bin/shutdown.sh -c ":shutdown()"

      or

      ./bin/shutdown.sh -c ":shutdown(timeout=30)"

      EAP 7.2 waits shutdown for the task thread to complete writing all access-log entries.
      However, EAP 7.3 does not wait. It only waits for 100 milliseconds because of the behavior change by WFCORE-1632. So, some log entries will be lost.

      Show
      To reproduce this issue, you can use either of the following methods to emulate slow down before completing to write all access log entries. Then, trigger shutdown during the slowdown. Use debugger to set thread-level breakpoint in Undertow's DefaultAccessLogReceiver#writeMessage() (or inside run()) Use byteman script to invoke Thread.sleep() in Undertow's DefaultAccessLogReceiver#writeMessage() (or inside run()) RULE DefaultAccessLogReceiver_writeMessage CLASS io.undertow.server.handlers.accesslog.DefaultAccessLogReceiver METHOD writeMessage AT ENTRY IF TRUE DO   traceStack( "-------------- io.undertow.server.handlers.accesslog.DefaultAccessLogReceiver#writeMessage() is invoked \n" );   Thread .sleep(10000L); // emulate slow down ENDRULE Then, follow the steps: 1. Send several requests to JBoss ab -n 10 -c 5 http: //127.0.0.1:8080/ 2. Shutdown JBoss (the same result happens regardless of using graceful shutdown or not) ./bin/shutdown.sh -c ":shutdown()" or ./bin/shutdown.sh -c ":shutdown(timeout=30)" EAP 7.2 waits shutdown for the task thread to complete writing all access-log entries. However, EAP 7.3 does not wait. It only waits for 100 milliseconds because of the behavior change by WFCORE-1632 . So, some log entries will be lost.

      access-log has a possibility to be lost during EAP 7.3 shutdown even if a graceful timeout is specified.

      If I understand correctly, access-log processing runs on a different thread from the application processing and the graceful shutdown does not care about it.

      Since EAP 7.3, WFCORE-1632 changed the shutdown behavior to wait only for 100ms (hard-coded). So, EAP 7.3 does not wait for completing a task worker thread processing access-log.

      I understand the purpose of WFCORE-1632. However, it might be good if we have an option to tune the wait time. (Of course, it would be difficult to know how long wait time is sufficient for completion. And specifying a large wait time can be a cause of long shutdown time. So, it's still questionable how it's useful.)
      Or, if it's possible to implement that the graceful shutdown can wait for access-log processing, it would be better. (This might be RFE?).

              rhn-cservice-bbaranow Bartosz Baranowski
              rhn-support-mmiura Masafumi Miura
              Votes:
              0 Vote for this issue
              Watchers:
              8 Start watching this issue

                Created:
                Updated:
                Resolved: