CODEWITHSUNDEEP
javajavaagents
WestFarmer
WestFarmer

Reputation: 765

thread started in javaagent blocking exit

In my javagent, I started a HttpServer:

public static void premain(String agentArgs, Instrumentation inst) throws InstantiationException, IOException {

        HttpServer server = HttpServer.create(new InetSocketAddress(8000), 0);

        server.createContext("/report", new ReportHandler());
        server.createContext("/data", new DataHandler());
        server.createContext("/stack", new StackHandler());
        ExecutorService es = Executors.newCachedThreadPool(new ThreadFactory() {
            int count = 0;
            @Override
            public Thread newThread(Runnable r) {
                Thread t = new Thread(r);
                t.setDaemon(true);
                t.setName("JDBCLD-HTTP-SERVER" + count++);
                return t;
            }
            
        });
        server.setExecutor(es);
        server.start();

        // how to properly close ?
        Runtime.getRuntime().addShutdownHook(new Thread() {
            @Override
            public void run() {
                server.stop(5);
                log.info("internal httpserver has been closed.");
                es.shutdown();
                try {
                    if (!es.awaitTermination(60, TimeUnit.SECONDS)) {
                        log.warn("executor service of internal httpserver not closing in 60 seconds");
                        es.shutdownNow();
                        if (!es.awaitTermination(60, TimeUnit.SECONDS))
                            log.error("executor service of internal httpserver not closing in 120 seconds, give up");
                    }else {
                        log.info("executor service of internal httpserver closed.");
                    }
                } catch (InterruptedException ie) {
                    log.warn("thread interrupted, shutdown executor service of internal httpserver");
                    es.shutdownNow();
                    Thread.currentThread().interrupt();
                }
            }
        });

    // other instrumention code ignored ...
}

testing programe:

public class AgentTest {

    public static void main(String[] args) throws SQLException {

        HikariConfig config = new HikariConfig();
        config.setJdbcUrl("jdbc:oracle:thin:@172.31.27.182:1521/pas");
        config.setUsername("pas");
        config.setPassword("pas");

        HikariDataSource ds = new HikariDataSource(config);
        Connection c = ds.getConnection();
        Connection c1 = ds.getConnection();
        
        c.getMetaData();
        
        try {
            Thread.sleep(1000 * 60 * 10);
        } catch (InterruptedException e) {
            e.printStackTrace();
            c.close();
            c1.close();
            ds.close();
        }
        
        c.close();
        c1.close();
        
        ds.close();
        
        
    }

}

When target jvm exit, I want the to stop that HttpServer. but when my testing java programe finish, main thread stoped but the whole jvm process won't terminate, shutdown hook in above code won't execute. if I click 'terminate' button in eclipse IDE, eclipse will show a error: enter image description here but at least jvm will exit, and my shutdown hook get invoked.

according to the java doc of java.lang.Runtime:

The Java virtual machine shuts down in response to two kinds of events:

The program exits normally, when the last non-daemon thread exits or when the exit (equivalently, System.exit) method is invoked, or The virtual machine is terminated in response to a user interrupt, such as typing ^C, or a system-wide event, such as user logoff or system shutdown.

com.sun.net.httpserver.HttpServer will started a non-daemon dispatcher thread, that thread will exit when HttpServer#stop get called, so I am facing a deadlock.

non-daemon thread not finish -> shutdown hook not triggered -> can't stop server -> non-daemon thread not finish

Any good idea? please note I can't modify code of targeting application.

UPDATES after apply kriegaex's answer

I added some logging to watch dog thread, and here is outputs:

2021-09-22 17:30:00.967 INFO  - Connnection@1594791957 acquired by 40A4F128987F8BD9C0EE6749895D1237
2021-09-22 17:30:00.968 DEBUG - Stack@40A4F128987F8BD9C0EE6749895D1237: 
java.lang.Throwable: 
    at com.zaxxer.hikari.pool.ProxyConnection.<init>(ProxyConnection.java:102)
    at com.zaxxer.hikari.pool.HikariProxyConnection.<init>(HikariProxyConnection.java)
    at com.zaxxer.hikari.pool.ProxyFactory.getProxyConnection(ProxyFactory.java)
    at com.zaxxer.hikari.pool.PoolEntry.createProxyConnection(PoolEntry.java:97)
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:192)
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:162)
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:100)
    at agenttest.AgentTest.main(AgentTest.java:19)
2021-09-22 17:30:00.969 INFO  - Connnection@686560878 acquired by 464555C270688B747CA211DE489B7730
2021-09-22 17:30:00.969 DEBUG - Stack@464555C270688B747CA211DE489B7730: 
java.lang.Throwable: 
    at com.zaxxer.hikari.pool.ProxyConnection.<init>(ProxyConnection.java:102)
    at com.zaxxer.hikari.pool.HikariProxyConnection.<init>(HikariProxyConnection.java)
    at com.zaxxer.hikari.pool.ProxyFactory.getProxyConnection(ProxyFactory.java)
    at com.zaxxer.hikari.pool.PoolEntry.createProxyConnection(PoolEntry.java:97)
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:192)
    at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:162)
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:100)
    at agenttest.AgentTest.main(AgentTest.java:20)
2021-09-22 17:30:00.971 DEBUG - Connnection@1594791957 used by getMetaData
2021-09-22 17:30:01.956 DEBUG - there is still 12 active threads, keep wathcing
2021-09-22 17:30:01.956 DEBUG - Reference Handler#true Finalizer#true Signal Dispatcher#true main#false server-timer#true Thread-2#false jdbcld-watch-dog#false Timer-0#true oracle.jdbc.driver.BlockSource.ThreadedCachingBlockSource.BlockReleaser#true InterruptTimer#true HikariPool-1 housekeeper#true HikariPool-1 connection adder#true 
2021-09-22 17:30:02.956 DEBUG - there is still 12 active threads, keep wathcing
2021-09-22 17:30:02.956 DEBUG - Reference Handler#true Finalizer#true Signal Dispatcher#true main#false server-timer#true Thread-2#false jdbcld-watch-dog#false Timer-0#true oracle.jdbc.driver.BlockSource.ThreadedCachingBlockSource.BlockReleaser#true InterruptTimer#true HikariPool-1 housekeeper#true HikariPool-1 connection adder#true 
2021-09-22 17:30:03.957 DEBUG - there is still 12 active threads, keep wathcing
2021-09-22 17:30:03.957 DEBUG - Reference Handler#true Finalizer#true Signal Dispatcher#true main#false server-timer#true Thread-2#false jdbcld-watch-dog#false Timer-0#true oracle.jdbc.driver.BlockSource.ThreadedCachingBlockSource.BlockReleaser#true InterruptTimer#true HikariPool-1 housekeeper#true HikariPool-1 connection adder#true 
2021-09-22 17:30:04.959 DEBUG - there is still 12 active threads, keep wathcing
2021-09-22 17:30:04.959 DEBUG - Reference Handler#true Finalizer#true Signal Dispatcher#true main#false server-timer#true Thread-2#false jdbcld-watch-dog#false Timer-0#true oracle.jdbc.driver.BlockSource.ThreadedCachingBlockSource.BlockReleaser#true InterruptTimer#true HikariPool-1 housekeeper#true HikariPool-1 connection adder#true 
2021-09-22 17:30:05.959 DEBUG - there is still 12 active threads, keep wathcing
2021-09-22 17:30:05.960 DEBUG - Reference Handler#true Finalizer#true Signal Dispatcher#true main#false server-timer#true Thread-2#false jdbcld-watch-dog#false Timer-0#true oracle.jdbc.driver.BlockSource.ThreadedCachingBlockSource.BlockReleaser#true InterruptTimer#true HikariPool-1 housekeeper#true HikariPool-1 connection adder#true 
2021-09-22 17:30:06.960 DEBUG - there is still 11 active threads, keep wathcing
2021-09-22 17:30:06.960 DEBUG - Reference Handler#true Finalizer#true Signal Dispatcher#true main#false server-timer#true Thread-2#false jdbcld-watch-dog#false Timer-0#true oracle.jdbc.driver.BlockSource.ThreadedCachingBlockSource.BlockReleaser#true InterruptTimer#true HikariPool-1 housekeeper#true 
2021-09-22 17:30:07.961 DEBUG - there is still 11 active threads, keep wathcing
2021-09-22 17:30:07.961 DEBUG - Reference Handler#true Finalizer#true Signal Dispatcher#true main#false server-timer#true Thread-2#false jdbcld-watch-dog#false Timer-0#true oracle.jdbc.driver.BlockSource.ThreadedCachingBlockSource.BlockReleaser#true InterruptTimer#true HikariPool-1 housekeeper#true 
2021-09-22 17:30:08.961 DEBUG - there is still 11 active threads, keep wathcing
2021-09-22 17:30:08.961 DEBUG - Reference Handler#true Finalizer#true Signal Dispatcher#true main#false server-timer#true Thread-2#false jdbcld-watch-dog#false Timer-0#true oracle.jdbc.driver.BlockSource.ThreadedCachingBlockSource.BlockReleaser#true InterruptTimer#true HikariPool-1 housekeeper#true 
2021-09-22 17:30:09.962 DEBUG - there is still 11 active threads, keep wathcing
2021-09-22 17:30:09.962 DEBUG - Reference Handler#true Finalizer#true Signal Dispatcher#true main#false server-timer#true Thread-2#false jdbcld-watch-dog#false Timer-0#true oracle.jdbc.driver.BlockSource.ThreadedCachingBlockSource.BlockReleaser#true InterruptTimer#true HikariPool-1 housekeeper#true 
2021-09-22 17:30:10.962 DEBUG - there is still 11 active threads, keep wathcing
2021-09-22 17:30:10.963 DEBUG - Reference Handler#true Finalizer#true Signal Dispatcher#true main#false server-timer#true Thread-2#false jdbcld-watch-dog#false Timer-0#true oracle.jdbc.driver.BlockSource.ThreadedCachingBlockSource.BlockReleaser#true InterruptTimer#true HikariPool-1 housekeeper#true 
2021-09-22 17:30:10.976 INFO  - Connnection@1594791957 released
2021-09-22 17:30:10.976 DEBUG - set connection count to 0 by stack hash 40A4F128987F8BD9C0EE6749895D1237
2021-09-22 17:30:10.976 INFO  - Connnection@686560878 released
2021-09-22 17:30:10.976 DEBUG - set connection count to 0 by stack hash 464555C270688B747CA211DE489B7730
2021-09-22 17:30:11.963 DEBUG - there is still 10 active threads, keep wathcing
2021-09-22 17:30:11.963 DEBUG - Reference Handler#true Finalizer#true Signal Dispatcher#true server-timer#true Thread-2#false jdbcld-watch-dog#false Timer-0#true oracle.jdbc.driver.BlockSource.ThreadedCachingBlockSource.BlockReleaser#true InterruptTimer#true DestroyJavaVM#false 
2021-09-22 17:30:12.964 DEBUG - there is still 10 active threads, keep wathcing

updates

I want to support all kinds of java application, include web application running with servlet containers and standard alone javase applications.

Upvotes: 0

Views: 450

Answers (1)

kriegaex
kriegaex

Reputation: 67407

Here is a little MCVE illustrating ewrammer's idea. I used the little byte-buddy-agent helper library for dynamically attaching an agent in order to make my example self-contained, starting the Java agent right from the main method. I omitted the 3 trivial no-op dummy handler classes necessary to run this example.

package org.acme.agent;

import com.sun.net.httpserver.HttpServer;
import net.bytebuddy.agent.ByteBuddyAgent;

import java.io.IOException;
import java.lang.instrument.Instrumentation;
import java.net.InetSocketAddress;
import java.util.Random;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.ThreadFactory;
import java.util.concurrent.TimeUnit;

public class Agent {

  public static void premain(String agentArgs, Instrumentation inst) throws IOException {
    HttpServer httpServer = HttpServer.create(new InetSocketAddress(8000), 0);
    ExecutorService executorService = getExecutorService(httpServer);
    Runtime.getRuntime().addShutdownHook(getShutdownHook(httpServer, executorService));
    // other instrumention code ignored ...
    startWatchDog();
  }

  private static ExecutorService getExecutorService(HttpServer server) {
    server.createContext("/report", new ReportHandler());
    server.createContext("/data", new DataHandler());
    server.createContext("/stack", new StackHandler());
    ExecutorService executorService = Executors.newCachedThreadPool(new ThreadFactory() {
      int count = 0;

      @Override
      public Thread newThread(Runnable r) {
        Thread t = new Thread(r);
        t.setDaemon(true);
        t.setName("JDBCLD-HTTP-SERVER" + count++);
        return t;
      }

    });
    server.setExecutor(executorService);
    server.start();
    return executorService;
  }

  private static Thread getShutdownHook(HttpServer httpServer, ExecutorService executorService) {
    return new Thread(() -> {
      httpServer.stop(5);
      System.out.println("Internal HTTP server has been stopped");
      executorService.shutdown();
      try {
        if (!executorService.awaitTermination(60, TimeUnit.SECONDS)) {
          System.out.println("Executor service of internal HTTP server not closing in 60 seconds");
          executorService.shutdownNow();
          if (!executorService.awaitTermination(60, TimeUnit.SECONDS))
            System.out.println("Executor service of internal HTTP server not closing in 120 seconds, giving up");
        }
        else {
          System.out.println("Executor service of internal HTTP server closed");
        }
      }
      catch (InterruptedException ie) {
        System.out.println("Thread interrupted, shutting down executor service of internal HTTP server");
        executorService.shutdownNow();
        Thread.currentThread().interrupt();
      }
    });
  }

  private static void startWatchDog() {
    ThreadGroup threadGroup = Thread.currentThread().getThreadGroup();
    while (threadGroup.getParent() != null)
      threadGroup = threadGroup.getParent();
    final ThreadGroup topLevelThreadGroup = threadGroup;
    // Plus 1, because of the monitoring thread we are going to start right below
    final int activeCount = topLevelThreadGroup.activeCount() + 1;

    new Thread(() -> {
      do {
        try {
          Thread.sleep(1000);
        }
        catch (InterruptedException ignored) {}
      } while (topLevelThreadGroup.activeCount() > activeCount);
      System.exit(0);
    }).start();
  }

  public static void main(String[] args) throws IOException {
    premain(null, ByteBuddyAgent.install());
    Random random = new Random();
    for (int i = 0; i < 5; i++) {
      new Thread(() -> {
        int threadDurationSeconds = 1 + random.nextInt(10);
        System.out.println("Starting thread with duration " + threadDurationSeconds + " s");
        try {
          Thread.sleep(threadDurationSeconds * 1000);
          System.out.println("Finishing thread after " + threadDurationSeconds + " s");
        }
        catch (InterruptedException ignored) {}
      }).start();
    }
  }
}

As you can see, this is basically your example code, refactored into a few helper methods for readability, plus the new watchdog method. It is quite straightforward.

This produces a console log like:

Starting thread with duration 6 s
Starting thread with duration 6 s
Starting thread with duration 8 s
Starting thread with duration 7 s
Starting thread with duration 5 s
Finishing thread after 5 s
Finishing thread after 6 s
Finishing thread after 6 s
Finishing thread after 7 s
Finishing thread after 8 s
internal httpserver has been closed.
executor service of internal httpserver closed.

Upvotes: 1

Related Questions