search

vert-x3 / vertx-web

HTTP web applications for Vert.x
Apache License 2.0
1.11k stars 534 forks source link

WebClient to get html from internet, but it doesn't call any of onSuccess() and onFailure() #2015

Open robinzt opened 3 years ago

robinzt commented 3 years ago

Questions

Use WebClient to get html from internet (for example: https://dgrtv.sun0769.com/index.php/online2/1), but it doesn't call any of onSuccess() and onFailure(). Usually it takes some time before occasionally occur, maybe some hours or some days.

I have changed from WebClient to Apache HttpClient. And Apache HttpClient always return the result: sucess or failure.

Version

vertx-web-client 4.1.0

Context

The code like:

log.info("{} enter refreshMediaUrl", name);
final Semaphore semaphore = new Semaphore(0);
webClient.getAbs(webUrl).timeout(DEFAULT_TIMEOUT_MILLI).send()
        .onSuccess(event -> {...  semaphore.release(); })
        .onFailure(event -> {...   semaphore.release();});

try {
    semaphore.acquire();
} catch (InterruptedException e) {
    log.warn("{} semaphore.acquire() {}", name, e);
}
log.info("{} exit refreshMediaUrl", name);

Do you have a reproducer?

Steps to reproduce

  1. Build project(vertx branch): https://github.com/robinzt/dgradio/tree/vertx
  2. Run it, or use docker run it
  3. Waiting some hours or some days ...
  4. The thread waits at semaphore.acquire(); And you cannot see any log in onSuccess() and onFailure()

Extra

robinzt commented 3 years ago

dgradio_log.zip

├── dgradio_log │   ├── 1008.log log of Radio 1008 │   ├── 104.log log of Radio 104 │   ├── 1075.log log of Radio 1075 │   ├── dgradio_heap.bin Dumped Java Heap │   ├── threads.log jstack │   └── vminfo.log jcmd VM.info

pigbayspy commented 3 years ago

Maybe it's not caused by WebClient.

I removed semaphore and it print the html result

class MainVerticle : AbstractVerticle() {

    private val webUrl = "https://dgrtv.sun0769.com/index.php/online2/1"

    private val default_timeout = 5000L

    override fun start() {
        // val proxyOption = proxyOptionsOf(host = "...", port = 8080, username = "...",
                password = "...", type = ProxyType.HTTP)
        // val option = webClientOptionsOf(proxyOptions = proxyOption)
        // val webClient = WebClient.create(vertx, option)
        val webClient = WebClient.create(vertx)
        webClient.getAbs(webUrl).timeout(default_timeout).send()
                .onSuccess {
                    val body = it.body()
                    println("body is ${body.toString(StandardCharsets.UTF_8)}")
                }
                .onFailure {
                    println("error is ${it.message}")
                }
        println("exit refreshMediaUrl")
    }
}
vietj commented 3 years ago

if that is executed from the event loop then the semaphore will self deadlock the application

vietj commented 3 years ago

is the code executed from the event loop ?

robinzt commented 3 years ago

is the code executed from the event loop ?

No, the code webClient.getAbs(webUrl) executed from a Timer Schedule thread.

    class RefreshMediaUrlRunner implements Runnable {
        @Override
        public void run() {
            refreshMediaUrl();
        }
    }

public void refreshMediaUrl() {
        log.info("{} enter refreshMediaUrl", name);
        final Semaphore semaphore = new Semaphore(0);
        webClient.getAbs(webUrl).timeout(DEFAULT_TIMEOUT_MILLI).send()
            .onSuccess(event -> {  DO SOMETHING;  semaphore.release();})
            .onFailure(event -> { DO SOMETHING;  semaphore.release();});
      try {
            semaphore.acquire();
        } catch (InterruptedException e) {
            log.warn("{} semaphore.acquire() {}", name, e);
        }
        log.info("{} exit refreshMediaUrl", name);
}

 refreshMediaUrlRunner = new RefreshMediaUrlRunner();
 scheduledExecutor = new ScheduledThreadPoolExecutor(2);
 scheduledExecutor.submit(refreshMediaUrlRunner);

I can explain it: The timer will schedule webClient.getAbs(webUrl) run once, and then wait by semaphore. When webClient got success from URL, it will reschedule itself after 8-12 minutes; And if failed, it will reschedule itself after 3 seconds (itself = webClient.getAbs(webUrl)).

In my first version, I don't use semaphore; But after running some hours or some days, I found webClient.getAbs(webUrl) have been called, but inner methods of onSuccess() and onFailure() NOT CALLED at all: NOTHING of log info or warn messages printed.

So I added the semaphore, let timer running thread wait semaphore.acquire() , and let onSuccess() and onFailure() call semaphore.release() at last. Yes, after some time, semaphore.acquire() waits forever, because onSuccess() and onFailure() NOT CALLED at all.

Please note: This situation is not immediate, but suddenly appears after a period of time. For example, Radio 104 started from 2021-07-26 03:11:53, but waits forever at 2021-07-27 17:39:43, the period of time is about 1 day plus 14-15 hours.

robinzt commented 3 years ago

Normal Log with HTTP Success: 2021-07-27 17:34:06,698 INFO [com.sky.dgr.mod.RadioStation] (pool-6-thread-1) 东莞电台声动104 enter refreshMediaUrl 2021-07-27 17:34:08,072 INFO [com.sky.dgr.mod.RadioStation] (vert.x-eventloop-thread-1) 东莞电台声动104 get MediaUrl success from https://dgrtv.sun0769.com/index.php/online2/3 2021-07-27 17:34:08,073 INFO [com.sky.dgr.mod.RadioStation] (vert.x-eventloop-thread-1) 东莞电台声动104 set MediaUrl=https://stream.sun0769.com/dgrtv1/mp4:tv12/index.m3u8?channel=1&t=1627407259&ttl=1200&key=d1f3934383f1db753484e51e736c7ae0 2021-07-27 17:34:08,073 INFO [com.sky.dgr.mod.RadioStation] (vert.x-eventloop-thread-1) 东莞电台声动104 ttl=1200, t=1627407259, seconds=1091, next run=Tue Jul 27 17:52:19 GMT 2021 2021-07-27 17:34:08,073 INFO [com.sky.dgr.mod.RadioStation] (vert.x-eventloop-thread-1) 东莞电台声动104 schedule refreshMediaUrlRunner java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@274dab3f[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@6afe1c85[Wrapped task = com.skywing.dgradio.model.RadioStation$RefreshMediaUrlRunner@4548bfc6]], delay=1090999973033 2021-07-27 17:34:08,073 INFO [com.sky.dgr.mod.RadioStation] (pool-6-thread-1) 东莞电台声动104 exit refreshMediaUrl

Normal Log with HTTP Failed: 2021-07-27 17:39:37,428 INFO [com.sky.dgr.mod.RadioStation] (pool-6-thread-2) 东莞电台声动104 enter refreshMediaUrl 2021-07-27 17:39:40,429 WARN [com.sky.dgr.mod.RadioStation] (vert.x-eventloop-thread-0) 东莞电台声动104 get MediaUrl failed from https://dgrtv.sun0769.com/index.php/online2/3 with io.vertx.core.http.impl.NoStackTraceTimeoutException: The timeout of 3000 ms has been exceeded when getting a connection to dgrtv.sun0769.com:443 2021-07-27 17:39:40,429 INFO [com.sky.dgr.mod.RadioStation] (vert.x-eventloop-thread-0) 东莞电台声动104 schedule refreshMediaUrlRunner java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@7e9b269b[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@7144f0bb[Wrapped task = com.skywing.dgradio.model.RadioStation$RefreshMediaUrlRunner@4548bfc6]], delay=2999965020 2021-07-27 17:39:40,430 INFO [com.sky.dgr.mod.RadioStation] (pool-6-thread-2) 东莞电台声动104 exit refreshMediaUrl

Wait Forever Log: 2021-07-27 17:39:43,430 INFO [com.sky.dgr.mod.RadioStation] (pool-6-thread-1) 东莞电台声动104 enter refreshMediaUrl

robinzt commented 3 years ago

Maybe it's not caused by WebClient.

I removed semaphore and it print the html result

class MainVerticle : AbstractVerticle() {

    private val webUrl = "https://dgrtv.sun0769.com/index.php/online2/1"

    private val default_timeout = 5000L

    override fun start() {
        // val proxyOption = proxyOptionsOf(host = "...", port = 8080, username = "...",
                password = "...", type = ProxyType.HTTP)
        // val option = webClientOptionsOf(proxyOptions = proxyOption)
        // val webClient = WebClient.create(vertx, option)
        val webClient = WebClient.create(vertx)
        webClient.getAbs(webUrl).timeout(default_timeout).send()
                .onSuccess {
                    val body = it.body()
                    println("body is ${body.toString(StandardCharsets.UTF_8)}")
                }
                .onFailure {
                    println("error is ${it.message}")
                }
        println("exit refreshMediaUrl")
    }
}

Please see https://github.com/vert-x3/vertx-web/issues/2015#issuecomment-896745366

pigbayspy commented 3 years ago

Maybe it's not caused by WebClient. I removed semaphore and it print the html result

class MainVerticle : AbstractVerticle() {

    private val webUrl = "https://dgrtv.sun0769.com/index.php/online2/1"

    private val default_timeout = 5000L

    override fun start() {
        // val proxyOption = proxyOptionsOf(host = "...", port = 8080, username = "...",
                password = "...", type = ProxyType.HTTP)
        // val option = webClientOptionsOf(proxyOptions = proxyOption)
        // val webClient = WebClient.create(vertx, option)
        val webClient = WebClient.create(vertx)
        webClient.getAbs(webUrl).timeout(default_timeout).send()
                .onSuccess {
                    val body = it.body()
                    println("body is ${body.toString(StandardCharsets.UTF_8)}")
                }
                .onFailure {
                    println("error is ${it.message}")
                }
        println("exit refreshMediaUrl")
    }
}

Please see #2015 (comment)

I changed my code to call the WebClient in ScheduledThreadPoolExecutor, and set a timer to fire it periodically. Everytime it got result.

public class ClientVerticle extends AbstractVerticle {

    private static final String WEB_URL = "https://dgrtv.sun0769.com/index.php/online2/1";

    private static final long DEFAULT_TIMEOUT_MILLI = 5000L;

    private WebClient webClient;

    private int count = 0;

    @Override
    public void start() throws Exception {
        webClient = WebClient.create(vertx);
        final Runnable refreshMediaUrlRunner = new RefreshMediaUrlRunner();
        ExecutorService scheduledExecutor = new ScheduledThreadPoolExecutor(2);
        vertx.setPeriodic(2000L, it -> {
            System.out.println("count is " + count);
            ++count;
            scheduledExecutor.submit(refreshMediaUrlRunner);
        });
    }

    private class RefreshMediaUrlRunner implements Runnable {
        @Override
        public void run() {
            refreshMediaUrl();
        }
    }

    public void refreshMediaUrl() {
        webClient.getAbs(WEB_URL).timeout(DEFAULT_TIMEOUT_MILLI).send()
                .onSuccess(event -> {
                    // String result = event.body().toString(StandardCharsets.UTF_8);
                    // System.out.println(result);
                    System.out.println("called success");
                })
                .onFailure(event -> {
                    // event.getCause().printStackTrace();
                    System.out.println("called fail");
                });
    }
}
robinzt commented 3 years ago

Maybe it's not caused by WebClient. I removed semaphore and it print the html result

class MainVerticle : AbstractVerticle() {

    private val webUrl = "https://dgrtv.sun0769.com/index.php/online2/1"

    private val default_timeout = 5000L

    override fun start() {
        // val proxyOption = proxyOptionsOf(host = "...", port = 8080, username = "...",
                password = "...", type = ProxyType.HTTP)
        // val option = webClientOptionsOf(proxyOptions = proxyOption)
        // val webClient = WebClient.create(vertx, option)
        val webClient = WebClient.create(vertx)
        webClient.getAbs(webUrl).timeout(default_timeout).send()
                .onSuccess {
                    val body = it.body()
                    println("body is ${body.toString(StandardCharsets.UTF_8)}")
                }
                .onFailure {
                    println("error is ${it.message}")
                }
        println("exit refreshMediaUrl")
    }
}

Please see #2015 (comment)

I changed my code to call the WebClient in ScheduledThreadPoolExecutor, and set a timer to fire it periodically. Everytime it got result.

public class ClientVerticle extends AbstractVerticle {

    private static final String WEB_URL = "https://dgrtv.sun0769.com/index.php/online2/1";

    private static final long DEFAULT_TIMEOUT_MILLI = 5000L;

    private WebClient webClient;

    private int count = 0;

    @Override
    public void start() throws Exception {
        webClient = WebClient.create(vertx);
        final Runnable refreshMediaUrlRunner = new RefreshMediaUrlRunner();
        ExecutorService scheduledExecutor = new ScheduledThreadPoolExecutor(2);
        vertx.setPeriodic(2000L, it -> {
            System.out.println("count is " + count);
            ++count;
            scheduledExecutor.submit(refreshMediaUrlRunner);
        });
    }

    private class RefreshMediaUrlRunner implements Runnable {
        @Override
        public void run() {
            refreshMediaUrl();
        }
    }

    public void refreshMediaUrl() {
        webClient.getAbs(WEB_URL).timeout(DEFAULT_TIMEOUT_MILLI).send()
                .onSuccess(event -> {
                    // String result = event.body().toString(StandardCharsets.UTF_8);
                    // System.out.println(result);
                    System.out.println("called success");
                })
                .onFailure(event -> {
                    // event.getCause().printStackTrace();
                    System.out.println("called fail");
                });
    }
}

Please see https://github.com/vert-x3/vertx-web/issues/2015#issuecomment-888150306 File: /dgradio_log/104.log, log of Radio 104

Please note: This situation is not immediate, but suddenly appears after a period of time -- some days or some hours.

For example, Radio 104 started from 2021-07-26 03:11:53, but waits forever at 2021-07-27 17:39:43, the period of time is about 1 day plus 14-15 hours.

First time of running (http success), at 2021-07-26 03:11:53: 2021-07-26 03:11:53,923 INFO [com.sky.dgr.mod.RadioStation] (pool-6-thread-1) 东莞电台声动104 enter refreshMediaUrl 2021-07-26 03:11:56,654 INFO [com.sky.dgr.mod.RadioStation] (vert.x-eventloop-thread-1) 东莞电台声动104 get MediaUrl success from https://dgrtv.sun0769.com/index.php/online2/3 ... 2021-07-26 03:11:56,670 INFO [com.sky.dgr.mod.RadioStation] (pool-6-thread-1) 东莞电台声动104 exit refreshMediaUrl

Last time of running (http failed), at 2021-07-27 17:39:37: 2021-07-27 17:39:37,428 INFO [com.sky.dgr.mod.RadioStation] (pool-6-thread-2) 东莞电台声动104 enter refreshMediaUrl 2021-07-27 17:39:40,429 WARN [com.sky.dgr.mod.RadioStation] (vert.x-eventloop-thread-0) 东莞电台声动104 get MediaUrl failed from https://dgrtv.sun0769.com/index.php/online2/3 with io.vertx.core.http.impl.NoStackTraceTimeoutException: The timeout of 3000 ms has been exceeded when getting a connection to dgrtv.sun0769.com:443 2021-07-27 17:39:40,430 INFO [com.sky.dgr.mod.RadioStation] (pool-6-thread-2) 东莞电台声动104 exit refreshMediaUrl

Wait forever at 2021-07-27 17:39:43 2021-07-27 17:39:43,430 INFO [com.sky.dgr.mod.RadioStation] (pool-6-thread-1) 东莞电台声动104 enter refreshMediaUrl