quarkus: Mailer stuck when sending a message from GraphQL endpoint

Describe the bug

Sorry me could you explain some situation with Mailer and GraphQL that happened in Quarkus version 2.13.4.Final (since 2.10.4.Final like i test). Why mail send stuck, when i send e-mail from GraphQL?

Example: i create project with two endpoints REST (io.quarkus:quarkus-resteasy-reactive-jsonb) and GraphQL (io.quarkus:quarkus-smallrye-graphql), and i use Mailer for mail send (io.quarkus:quarkus-mailer).

REST:

package io.quarkus.explore.testclient.graphql;

import io.quarkus.mailer.Mail;
import io.quarkus.mailer.Mailer;
import javax.inject.Inject;
import javax.ws.rs.GET;
import javax.ws.rs.Path;

@Path("")
public class TestMailRest {

    @Inject
    Mailer mailer;

    @GET
    @Path("/mail")
    public void send() {
        mailer.send(Mail.withText("to@acme.org", "A simple email from quarkus", "This is my body"));
    }

}

GraphQL:

package io.quarkus.explore.testclient.graphql;

import io.quarkus.mailer.Mail;
import io.quarkus.mailer.Mailer;
import javax.inject.Inject;
import org.eclipse.microprofile.graphql.GraphQLApi;
import org.eclipse.microprofile.graphql.Query;

@GraphQLApi
public class TestMailGraphQL {

    @Inject
    Mailer mailer;

    @Query("checkMailSend")
    public String checkMailSend(String targetAddress) {
        mailer.send(Mail.withText("to@acme.org", "A simple email from quarkus", "This is my body"));
        return "Mail test!";
    }

}

Scenario - 1: If i run project, and then execute REST GET to /mail all will be fine and message send complete, like in documentation examples.

Scenario - 2: !Restart project!. And then, if i run it again and execute GraphQL operation:

query TestMail {
  checkMailSend(targetAddress: "NotMatter")
}

then application stuck and i have error:

     2022-11-09 09:23:31,247 WARN  [io.ver.cor.imp.BlockedThreadChecker] (vertx-blocked-thread-checker) Thread Thread[vert.x-worker-thread-0,5,main] has been blocked for 60392 ms, time limit is 60000 ms: io.vertx.core.VertxException: Thread blockedce:quarkusDev
        at java.base@17.0.5/jdk.internal.misc.Unsafe.park(Native Method)
        at java.base@17.0.5/java.util.concurrent.locks.LockSupport.park(LockSupport.java:211)
        at java.base@17.0.5/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:715)
        at java.base@17.0.5/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1047)
        at java.base@17.0.5/java.util.concurrent.CountDownLatch.await(CountDownLatch.java:230)
        at io.smallrye.mutiny.operators.uni.UniBlockingAwait.await(UniBlockingAwait.java:67)
        at io.smallrye.mutiny.groups.UniAwait.atMost(UniAwait.java:65)
        at io.smallrye.mutiny.groups.UniAwait.indefinitely(UniAwait.java:46)
        at io.quarkus.mailer.runtime.BlockingMailerImpl.send(BlockingMailerImpl.java:21)
        at io.quarkus.mailer.runtime.BlockingMailerImpl_Subclass.send$$superforward1(Unknown Source)
        at io.quarkus.mailer.runtime.BlockingMailerImpl_Subclass$$function$$1.apply(Unknown Source)
        at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:53)
        at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.proceed(InvocationInterceptor.java:62)
        at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.monitor(InvocationInterceptor.java:49)
        at io.quarkus.arc.runtime.devconsole.InvocationInterceptor_Bean.intercept(Unknown Source)
        at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
        at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:40)
        at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
        at io.quarkus.mailer.runtime.BlockingMailerImpl_Subclass.send(Unknown Source)
        at io.quarkus.mailer.runtime.BlockingMailerImpl_ClientProxy.send(Unknown Source)
        at io.quarkus.explore.testclient.graphql.TestMailGraphQL.checkMailSend(TestMailGraphQL.java:17)
        at io.quarkus.explore.testclient.graphql.TestMailGraphQL_Subclass.checkMailSend$$superforward1(Unknown Source)
        at io.quarkus.explore.testclient.graphql.TestMailGraphQL_Subclass$$function$$1.apply(Unknown Source)
        at io.quarkus.arc.impl.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:53)
        at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.proceed(InvocationInterceptor.java:62)
        at io.quarkus.arc.runtime.devconsole.InvocationInterceptor.monitor(InvocationInterceptor.java:49)
        at io.quarkus.arc.runtime.devconsole.InvocationInterceptor_Bean.intercept(Unknown Source)
        at io.quarkus.arc.impl.InterceptorInvocation.invoke(InterceptorInvocation.java:41)
        at io.quarkus.arc.impl.AroundInvokeInvocationContext.perform(AroundInvokeInvocationContext.java:40)
        at io.quarkus.arc.impl.InvocationContexts.performAroundInvoke(InvocationContexts.java:32)
        at io.quarkus.explore.testclient.graphql.TestMailGraphQL_Subclass.checkMailSend(Unknown Source)
        at java.base@17.0.5/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base@17.0.5/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
        at java.base@17.0.5/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base@17.0.5/java.lang.reflect.Method.invoke(Method.java:568)
        at io.smallrye.graphql.execution.datafetcher.helper.ReflectionInvoker.invoke(ReflectionInvoker.java:92)
        at io.quarkus.smallrye.graphql.runtime.spi.datafetcher.QuarkusDefaultDataFetcher.lambda$invokeAndTransformBlocking$0(QuarkusDefaultDataFetcher.java:62)
        at io.quarkus.smallrye.graphql.runtime.spi.datafetcher.QuarkusDefaultDataFetcher$$Lambda$1516/0x0000000800e2d308.call(Unknown Source)
        at io.smallrye.context.impl.wrappers.SlowContextualCallable.call(SlowContextualCallable.java:21)
        at io.quarkus.smallrye.graphql.runtime.spi.datafetcher.BlockingHelper.lambda$runBlocking$0(BlockingHelper.java:27)
        at io.quarkus.smallrye.graphql.runtime.spi.datafetcher.BlockingHelper$$Lambda$1517/0x0000000800e2d748.handle(Unknown Source)
        at io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)
        at io.vertx.core.impl.ContextImpl$$Lambda$1304/0x0000000801313a98.handle(Unknown Source)
        at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)
        at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157)
        at io.vertx.core.impl.ContextImpl$$Lambda$1302/0x0000000801313440.run(Unknown Source)
        at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)
        at io.vertx.core.impl.TaskQueue$$Lambda$1266/0x000000080129f6a0.run(Unknown Source)
        at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)
        at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2449)
        at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1478)
        at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
        at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base@17.0.5/java.lang.Thread.run(Thread.java:833)

Scenario - 3: !Restart project!. And then, if i run REST GET before GraphQL and then i execute GraphQL query all will be fine again. GraphQL mail send work if you execute REST before it.

Important: it is work great in 2.7.2.Final without any problem, but in new versions it is broke for me.

Expected behavior

Scenario - 1: - Work well!

Scenario - 2: - Mailer send my message via GraphQL.

Scenario - 2: - I no need execute REST before GraphQL.

Actual behavior

Scenario - 1: - Work well!

Scenario - 2: - Mailer stuck and thread blocked error happened.

Scenario - 2: - Work strange, because i need execute REST before GraphQL.

How to Reproduce?

No response

Output of uname -a or ver

No response

Output of java -version

JDK 17 from Gradle Java toolchain

GraalVM version (if different from Java)

No response

Quarkus version or git rev

2.13.4.Final

Build tool (ie. output of mvnw --version or gradlew --version)

7.5.1

Additional information

No response

About this issue

  • Original URL
  • State: closed
  • Created 2 years ago
  • Comments: 22 (14 by maintainers)

Most upvoted comments

Thanks a lot for the reproducer, that helps tremendously! I confirm I can reproduce the problem, not yet sure though how to fix it. In any case, it seems that switching to a reactive mailer fixes the issue - I guess this could be used as a workaround. The equivalent rewrite of your code would be:

@Inject
ReactiveMailer reactiveMailer;

@Query("checkMailSend")
public Uni<String> checkMailSend(String targetAddress) {
    var mailToSend = Mail.withText(
            targetAddress,
            "A simple email from quarkus",
            "This is my body");
    return reactiveMailer.send(mailToSend)
        .onItem().transform(v -> "Mail test!");
    }

This makes me think that there’s some issue with losing some context when using the non-reactive mailer (which actually calls the reactive mailer internally). For now I’d suggest trying with the reactive mailer…

+2
jmartisk on Nov 9, 2022

So, to explain.

This cannot work:

        Vertx vertx = Vertx.vertx();
        MailConfig config = new MailConfig()
                .setAuthMethods("DIGEST-MD5 CRAM-SHA256 CRAM-SHA1 CRAM-MD5 PLAIN LOGIN")
                .setHostname("smtp.gmail.com")
                .setPort(587)
                .setStarttls(StartTLSOptions.REQUIRED)
                .setUsername("clement.escoffier@gmail.com")
                .setPassword("this is a secret");
        var c = MailClient.create(vertx, config);
        vertx.executeBlocking(p -> {
            c.sendMail(new MailMessage().setFrom("clement.escoffier@gmail.com")
                            .setTo("clement@redhat.com")
                            .setSubject("test from execute blocking").setText("hello, first test of the day"))
                    .toCompletionStage().toCompletableFuture().join(); // this will block forever
            p.complete();
        }).toCompletionStage().toCompletableFuture().join();

This executeBlocking is ordered, meaning that it waits for the completion of the action before being able to execute another action. However, sendMail returns a Future that tries to invoke its attached callbacks in the same context (that’s the reactive model), but it cannot work, as you can’t execute these callbacks until the sendMail operation completes, which is waiting for the callbacks. In order words: we’re stuck.

The solution is to lift the order constraint and use executeBlocking(...., false).

@phillip-kruger @jmartisk do you know where is the executeBlocking and if the order must be preserved?

BTW, many async client will have the same issue, not only the mailer.

+1
cescoffier on Nov 16, 2022

It’s weird that the sending operation takes over a minute, perhaps there’s a swallowed exception somewhere? Could you enable more detailed logs and see if there are any suspicious errors apart from the BlockedThreadChecker warning? Or provide a reproducer project that we could use.

+1
jmartisk on Nov 9, 2022
Read more comments on GitHub
← quarkus: LogManager error of type FORMAT_FAILURE: Formatting error
quarkus: Malformed DNS message on MacOS →