春季的 @Async 不会立即返回

huangapple
未分类评论48阅读模式
英文:

Spring @Async doesn't return immediately

问题

我有一个中等大小的 Spring Boot 应用程序，使用了 Spring Data REST、Spring HATEOAS、Spring JPA 和 Hibernate。

我在使用 @Async 时遇到了一些问题：使用这种方式注解的方法，即使为其创建了一个新的线程执行（Spring 文档），但调用者并不会立即返回。

以下是我的配置：

@Configuration
@EnableAsync
public class AsyncConfiguration implements AsyncConfigurer {
    
    @Override
    public Executor getAsyncExecutor() {
        ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
        executor.setCorePoolSize(2);
        executor.setMaxPoolSize(10);
        executor.setQueueCapacity(500);
        executor.setThreadNamePrefix("myThreadAsync");
        executor.initialize();
        return executor;
    }
}

以下是带有 @Async 方法的组件：

@Component
@Log4j2
public class OrderCommunicationBuilder {
    
    @Async
    public void sendEmailPendingOrder(Tenant tenant, String orderSid, String paymentDetails) {
        // 一些操作
    }
}

以下是调用该方法的服务：

@Service
@Transactional(value = "managementTransactionManager")
@Log4j2
public class TenantService {
    
    public Optional<Order> upgradePlanForCurrentTenant(Plan plan, int users, int stores, PaymentType paymentType) {
        // 一些通过 Hibernate 在数据库中保存数据的操作
        orderCommunicationBuilder.sendEmailPendingOrder(order.getTenant(), order.getSid(),order.getPaymentDetails()); // 这是异步调用
        // 其他操作
        return Optional.ofNullable(order);
    }
}

以下是使用该服务的 REST 控制器：

@Profile({"dev", "stage", "prod"})
@RepositoryRestController
@RequestMapping(path = "/api/v1")
@Log4j2
public class TenantController {
    
    @PreAuthorize("isAuthenticated()")
    @PostMapping(path = "/tenants/current/subscription/renewal")
    public ResponseEntity<?> renewal(@RequestBody Map<String, Object> data, PersistentEntityResourceAssembler resourceAssembler) {
        // 一些操作
        Optional<Order> optionalOrder = tenantService.upgradePlanForCurrentTenant(plan, users, stores, paymentType); // 此调用会等待，直到 OrderCommunicationBuilder#sendEmailPendingOrder 完成
        if (optionalOrder.isPresent()) {
            return ResponseEntity.ok(resourceAssembler.toModel(optionalOrder.get()));
        }
        throw new InternalException(ExceptionCode.INTERNAL_ERROR);
    }
}

我启用了 Spring 的日志，我看到当调用 sendEmailPendingOrder() 方法时会创建一个新的线程，然而 TenantController 会一直等待，直到 OrderCommunicationBuilder#sendEmailPendingOrder 完成，但实际上不应该如此。

一些相关的日志：

（日志内容已省略）

1: Spring 文档链接

英文:

I've a medium size Spring Boot application using: Spring Data REST, Spring HATEOAS, Spring JPA, Hibernate.

I've some problems using @Async: the method annotated in such way doesn't return immediately to the caller even if it's created a new thread for the execution (Spring doc).

This is my configuration:

@Configuration
@EnableAsync
public class AsyncConfiguration implements AsyncConfigurer {

    @Override
    public Executor getAsyncExecutor() {
        ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
        executor.setCorePoolSize(2);
        executor.setMaxPoolSize(10);
        executor.setQueueCapacity(500);
        executor.setThreadNamePrefix(&quot;myThreadAsync&quot;);
        executor.initialize();
        return executor;
    }
}

this is the component with @Async method:

@Component
@Log4j2
public class OrderCommunicationBuilder {


    @Async
    public void sendEmailPendingOrder(Tenant tenant, String orderSid, String paymentDetails) {

       // Some stuff
    }
}

and this is the service that calls that method:

@Service
@Transactional(value = &quot;managementTransactionManager&quot;)
@Log4j2
public class TenantService {

     public Optional&lt;Order&gt; upgradePlanForCurrentTenant(Plan plan, int users, int stores, PaymentType paymentType) {
      //some stuff saving data via HIbernate in DB

      orderCommunicationBuilder.sendEmailPendingOrder(order.getTenant(), order.getSid(),order.getPaymentDetails());//this is async

      //some other stuff
      return Optional.ofNullable(order);
    }
}

This is the REST controller that uses the service:

@Profile({&quot;dev&quot;, &quot;stage&quot;, &quot;prod&quot;})
@RepositoryRestController
@RequestMapping(path = &quot;/api/v1&quot;)
@Log4j2
public class TenantController {

    @PreAuthorize(&quot;isAuthenticated()&quot;)
    @PostMapping(path = &quot;/tenants/current/subscription/renewal&quot;)
    public ResponseEntity&lt;?&gt; renewal(@RequestBody Map&lt;String, Object&gt; data, PersistentEntityResourceAssembler resourceAssembler) {
        //Some stuff
        Optional&lt;Order&gt; optionalOrder = tenantService.upgradePlanForCurrentTenant(plan, users, stores, paymentType); //this call remains pending until OrderCommunicationBuilder#sendEmailPendingOrder doesn&#39;t finish
        if (optionalOrder.isPresent()) {
            return ResponseEntity.ok(resourceAssembler.toModel(optionalOrder.get()));
        }
        throw new InternalException(ExceptionCode.INTERNAL_ERROR);
    }

}

I enabled Spring's log and I see that a new thread is created when the method sendEmailPendingOrder() is called, hovewer the TenantController remains pending until OrderCommunicationBuilder#sendEmailPendingOrder ends but it should not!

Some relevant log:

 07/04/2020 15:23:11,989 DEBUG http-nio-8082-exec-9 FilterChainProxy:328 - /api/v1/tenants/current/subscription/renewal at position 1 of 14 in additional filter chain; firing Filter: &#39;WebAsyncManagerIntegrationFilter&#39;
07/04/2020 15:23:11,989 DEBUG http-nio-8082-exec-9 FilterChainProxy:328 - /api/v1/tenants/current/subscription/renewal at position 2 of 14 in additional filter chain; firing Filter: &#39;SecurityContextPersistenceFilter&#39;
07/04/2020 15:23:11,989 DEBUG http-nio-8082-exec-9 HttpSessionSecurityContextRepository:173 - No HttpSession currently exists
07/04/2020 15:23:11,989 DEBUG http-nio-8082-exec-9 HttpSessionSecurityContextRepository:117 - No SecurityContext was available from the HttpSession: null. A new one will be created.
07/04/2020 15:23:11,989 DEBUG http-nio-8082-exec-9 FilterChainProxy:328 - /api/v1/tenants/current/subscription/renewal at position 3 of 14 in additional filter chain; firing Filter: &#39;HeaderWriterFilter&#39;
07/04/2020 15:23:11,990 DEBUG http-nio-8082-exec-9 FilterChainProxy:328 - /api/v1/tenants/current/subscription/renewal at position 4 of 14 in additional filter chain; firing Filter: &#39;LogoutFilter&#39;
07/04/2020 15:23:11,990 DEBUG http-nio-8082-exec-9 OrRequestMatcher:65 - Trying to match using Ant [pattern=&#39;/logout&#39;, GET]
07/04/2020 15:23:11,990 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:157 - Request &#39;POST /api/v1/tenants/current/subscription/renewal&#39; doesn&#39;t match &#39;GET /logout&#39;
07/04/2020 15:23:11,990 DEBUG http-nio-8082-exec-9 OrRequestMatcher:65 - Trying to match using Ant [pattern=&#39;/logout&#39;, POST]
07/04/2020 15:23:11,990 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/logout&#39;
07/04/2020 15:23:11,990 DEBUG http-nio-8082-exec-9 OrRequestMatcher:65 - Trying to match using Ant [pattern=&#39;/logout&#39;, PUT]
07/04/2020 15:23:11,990 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:157 - Request &#39;POST /api/v1/tenants/current/subscription/renewal&#39; doesn&#39;t match &#39;PUT /logout&#39;
07/04/2020 15:23:11,990 DEBUG http-nio-8082-exec-9 OrRequestMatcher:65 - Trying to match using Ant [pattern=&#39;/logout&#39;, DELETE]
07/04/2020 15:23:11,990 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:157 - Request &#39;POST /api/v1/tenants/current/subscription/renewal&#39; doesn&#39;t match &#39;DELETE /logout&#39;
07/04/2020 15:23:11,990 DEBUG http-nio-8082-exec-9 OrRequestMatcher:72 - No matches found
07/04/2020 15:23:11,990 DEBUG http-nio-8082-exec-9 FilterChainProxy:328 - /api/v1/tenants/current/subscription/renewal at position 5 of 14 in additional filter chain; firing Filter: &#39;TenantFilter&#39;
07/04/2020 15:23:11,990 DEBUG http-nio-8082-exec-9 FilterChainProxy:328 - /api/v1/tenants/current/subscription/renewal at position 6 of 14 in additional filter chain; firing Filter: &#39;JwtAuthenticationTokenFilter&#39;
07/04/2020 15:23:12,138 DEBUG http-nio-8082-exec-9 FilterChainProxy:328 - /api/v1/tenants/current/subscription/renewal at position 7 of 14 in additional filter chain; firing Filter: &#39;CookieAuthFilter&#39;
07/04/2020 15:23:12,138 DEBUG http-nio-8082-exec-9 FilterChainProxy:328 - /api/v1/tenants/current/subscription/renewal at position 8 of 14 in additional filter chain; firing Filter: &#39;UsernamePasswordAuthenticationFilter&#39;
07/04/2020 15:23:12,138 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/login&#39;
07/04/2020 15:23:12,138 DEBUG http-nio-8082-exec-9 FilterChainProxy:328 - /api/v1/tenants/current/subscription/renewal at position 9 of 14 in additional filter chain; firing Filter: &#39;RequestCacheAwareFilter&#39;
07/04/2020 15:23:12,138 DEBUG http-nio-8082-exec-9 HttpSessionRequestCache:95 - saved request doesn&#39;t match
07/04/2020 15:23:12,138 DEBUG http-nio-8082-exec-9 FilterChainProxy:328 - /api/v1/tenants/current/subscription/renewal at position 10 of 14 in additional filter chain; firing Filter: &#39;SecurityContextHolderAwareRequestFilter&#39;
07/04/2020 15:23:12,138 DEBUG http-nio-8082-exec-9 FilterChainProxy:328 - /api/v1/tenants/current/subscription/renewal at position 11 of 14 in additional filter chain; firing Filter: &#39;AnonymousAuthenticationFilter&#39;

07/04/2020 15:23:12,138 DEBUG http-nio-8082-exec-9 FilterChainProxy:328 - /api/v1/tenants/current/subscription/renewal at position 12 of 14 in additional filter chain; firing Filter: &#39;SessionManagementFilter&#39;
07/04/2020 15:23:12,139 DEBUG http-nio-8082-exec-9 CompositeSessionAuthenticationStrategy:87 - Delegating to org.springframework.security.web.authentication.session.ChangeSessionIdAuthenticationStrategy@7ce03100
07/04/2020 15:23:12,139 DEBUG http-nio-8082-exec-9 HttpSessionSecurityContextRepository:426 - HttpSession being created as SecurityContext is non-default

07/04/2020 15:23:12,139 DEBUG http-nio-8082-exec-9 FilterChainProxy:328 - /api/v1/tenants/current/subscription/renewal at position 13 of 14 in additional filter chain; firing Filter: &#39;ExceptionTranslationFilter&#39;
07/04/2020 15:23:12,139 DEBUG http-nio-8082-exec-9 FilterChainProxy:328 - /api/v1/tenants/current/subscription/renewal at position 14 of 14 in additional filter chain; firing Filter: &#39;FilterSecurityInterceptor&#39;
07/04/2020 15:23:12,139 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:157 - Request &#39;POST /api/v1/tenants/current/subscription/renewal&#39; doesn&#39;t match &#39;OPTIONS /**&#39;
07/04/2020 15:23:12,139 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/alexa&#39;
07/04/2020 15:23:12,139 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/socket/**&#39;
07/04/2020 15:23:12,139 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/images/**&#39;
07/04/2020 15:23:12,139 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/resources/templates/**&#39;
07/04/2020 15:23:12,140 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/api/v1/notifications/**&#39;
07/04/2020 15:23:12,140 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/actuator/**&#39;
07/04/2020 15:23:12,140 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/v2/api-docs&#39;
07/04/2020 15:23:12,140 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/swagger-accounts/configuration/ui&#39;
07/04/2020 15:23:12,140 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/swagger-accounts&#39;
07/04/2020 15:23:12,140 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/swagger-accounts/configuration/security&#39;
07/04/2020 15:23:12,140 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/swagger-ui.html&#39;
07/04/2020 15:23:12,140 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/webjars/**&#39;
07/04/2020 15:23:12,140 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/swagger-resources/**&#39;
07/04/2020 15:23:12,141 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/api/v1/public/**&#39;
07/04/2020 15:23:12,141 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/api/v1/auth/**&#39;
07/04/2020 15:23:12,141 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/api/v1/formLogin/**&#39;
07/04/2020 15:23:12,141 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/api/v1/logout&#39;
07/04/2020 15:23:12,141 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/api/v1/agents/verifyEmail&#39;
07/04/2020 15:23:12,141 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/api/v1/agents/**/verificationToken&#39;
07/04/2020 15:23:12,141 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/api/v1/agents/**/resetPassword&#39;
07/04/2020 15:23:12,141 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/api/v1/agents/**/verifyPasswordReset&#39;
07/04/2020 15:23:12,142 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/api/v1/agents/**/changePassword&#39;
07/04/2020 15:23:12,142 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/api/v1/errors/**&#39;
07/04/2020 15:23:12,142 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/api/v1/verifyCaptcha&#39;
07/04/2020 15:23:12,142 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/api/v1/ping&#39;
07/04/2020 15:23:12,142 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/api/v1/tenants&#39;
07/04/2020 15:23:12,142 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:157 - Request &#39;POST /api/v1/tenants/current/subscription/renewal&#39; doesn&#39;t match &#39;GET /api/v1/tenants/**/availability&#39;
07/04/2020 15:23:12,142 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/api/v1/alcon/**/image&#39;
07/04/2020 15:23:12,142 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/api/v1/avm/**/image&#39;
07/04/2020 15:23:12,142 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/api/v1/marcolin/**/image&#39;
07/04/2020 15:23:12,142 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/api/v1/trevi/**/image&#39;
07/04/2020 15:23:12,143 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/api/v1/area98/**/image&#39;
07/04/2020 15:23:12,143 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:177 - Checking match of request : &#39;/api/v1/tenants/current/subscription/renewal&#39;; against &#39;/api/v1/diesse/**/image&#39;
07/04/2020 15:23:12,143 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:157 - Request &#39;POST /api/v1/tenants/current/subscription/renewal&#39; doesn&#39;t match &#39;GET /api/v1&#39;
07/04/2020 15:23:12,143 DEBUG http-nio-8082-exec-9 AntPathRequestMatcher:167 - Request &#39;/api/v1/tenants/current/subscription/renewal&#39; matched by universal pattern &#39;/**&#39;
07/04/2020 15:23:12,143 DEBUG http-nio-8082-exec-9 FilterSecurityInterceptor:219 - Secure object: FilterInvocation: URL: /api/v1/tenants/current/subscription/renewal; Attributes: [authenticated]

07/04/2020 15:23:12,143 DEBUG http-nio-8082-exec-9 AffirmativeBased:66 - Voter: org.springframework.security.web.access.expression.WebExpressionVoter@39ef6da6, returned: 1
07/04/2020 15:23:12,143 DEBUG http-nio-8082-exec-9 FilterSecurityInterceptor:243 - Authorization successful
07/04/2020 15:23:12,143 DEBUG http-nio-8082-exec-9 FilterSecurityInterceptor:256 - RunAsManager did not change Authentication object
07/04/2020 15:23:12,144 DEBUG http-nio-8082-exec-9 FilterChainProxy:313 - /api/v1/tenants/current/subscription/renewal reached end of additional filter chain; proceeding with original chain
07/04/2020 15:23:12,144 DEBUG http-nio-8082-exec-9 DispatcherServlet:91 - POST &quot;/api/v1/tenants/current/subscription/renewal&quot;, parameters={}
07/04/2020 15:23:12,144 DEBUG http-nio-8082-exec-9 RequestMappingHandlerMapping:414 - Mapped to com.test.server.rest.controllers.tenants.TenantController#renewal(Map, PersistentEntityResourceAssembler)
07/04/2020 15:23:12,145 DEBUG http-nio-8082-exec-9 RequestResponseBodyMethodProcessor:91 - Read &quot;application/json;charset=UTF-8&quot; to [{plan=http://xx.xx.xx.xx:8082/api/v1/plans/4, users=5, stores=2, paymentType=BANK_TRANSFER}]
07/04/2020 15:23:12,145 DEBUG http-nio-8082-exec-9 MethodSecurityInterceptor:219 - Secure object: ReflectiveMethodInvocation: public org.springframework.http.ResponseEntity com.test.server.rest.controllers.tenants.TenantController.renewal(java.util.Map,org.springframework.data.rest.webmvc.PersistentEntityResourceAssembler); target is of class [com.test.server.rest.controllers.tenants.TenantController]; Attributes: [[authorize: &#39;isAuthenticated()&#39;, filter: &#39;null&#39;, filterTarget: &#39;null&#39;]]
07/04/2020 15:23:12,146 DEBUG http-nio-8082-exec-9 AffirmativeBased:66 - Voter: org.springframework.security.access.prepost.PreInvocationAuthorizationAdviceVoter@a3c2c4e, returned: 1
07/04/2020 15:23:12,146 DEBUG http-nio-8082-exec-9 MethodSecurityInterceptor:243 - Authorization successful
07/04/2020 15:23:12,146 DEBUG http-nio-8082-exec-9 MethodSecurityInterceptor:256 - RunAsManager did not change Authentication object
07/04/2020 15:23:12,203 DEBUG http-nio-8082-exec-9 DataSourceUtils:186 - Setting JDBC Connection [HikariProxyConnection@1902501765 wrapping com.mysql.cj.jdbc.ConnectionImpl@511ad0dd] read-only
07/04/2020 15:23:12,374 DEBUG http-nio-8082-exec-9 DataSourceUtils:250 - Resetting read-only flag of JDBC Connection [HikariProxyConnection@1902501765 wrapping com.mysql.cj.jdbc.ConnectionImpl@511ad0dd]
07/04/2020 15:23:12,436  WARN http-nio-8082-exec-9 EntityManagerEnabledFilterAspect:34 - Unable to enable filter
07/04/2020 15:23:12,437  WARN http-nio-8082-exec-9 EntityManagerStoreFilterAspect:41 - Unable to enable filter
07/04/2020 15:23:12,437  WARN http-nio-8082-exec-9 EntityManagerStoreFilterAspect:41 - Unable to enable filter
07/04/2020 15:23:12,494  INFO http-nio-8082-exec-9 TenantService:387 - Tenant pianetatecno (31) is renewing plan
07/04/2020 15:23:12,495 DEBUG http-nio-8082-exec-9 MethodSecurityInterceptor:219 - Secure object: ReflectiveMethodInvocation: public abstract long com.test.management.repositories.orders.OrderRepository.countByDateWithPaymentStatus(java.time.Instant,com.test.management.model.enums.PaymentStatus,long); target is of class [com.sun.proxy.$Proxy360]; Attributes: [[authorize: &#39;isAuthenticated()&#39;, filter: &#39;null&#39;, filterTarget: &#39;null&#39;]]
07/04/2020 15:23:12,495 DEBUG http-nio-8082-exec-9 AffirmativeBased:66 - Voter: org.springframework.security.access.prepost.PreInvocationAuthorizationAdviceVoter@a3c2c4e, returned: 1
07/04/2020 15:23:12,495 DEBUG http-nio-8082-exec-9 MethodSecurityInterceptor:243 - Authorization successful
07/04/2020 15:23:12,495 DEBUG http-nio-8082-exec-9 MethodSecurityInterceptor:256 - RunAsManager did not change Authentication object
07/04/2020 15:23:12,496  WARN http-nio-8082-exec-9 EntityManagerEnabledFilterAspect:34 - Unable to enable filter
07/04/2020 15:23:12,496  WARN http-nio-8082-exec-9 EntityManagerStoreFilterAspect:41 - Unable to enable filter
07/04/2020 15:23:12,496  WARN http-nio-8082-exec-9 EntityManagerStoreFilterAspect:41 - Unable to enable filter
07/04/2020 15:23:12,554 DEBUG http-nio-8082-exec-9 MethodSecurityInterceptor:219 - Secure object: ReflectiveMethodInvocation: public abstract long com.test.management.repositories.orders.OrderRepository.countPendingOrdersByPaymentType(com.test.management.model.enums.PaymentType,java.lang.String); target is of class [com.sun.proxy.$Proxy360]; Attributes: [[authorize: &#39;isAuthenticated()&#39;, filter: &#39;null&#39;, filterTarget: &#39;null&#39;]]
07/04/2020 15:23:12,554 DEBUG http-nio-8082-exec-9 AffirmativeBased:66 - Voter: org.springframework.security.access.prepost.PreInvocationAuthorizationAdviceVoter@a3c2c4e, returned: 1
07/04/2020 15:23:12,555 DEBUG http-nio-8082-exec-9 MethodSecurityInterceptor:243 - Authorization successful
07/04/2020 15:23:12,555 DEBUG http-nio-8082-exec-9 MethodSecurityInterceptor:256 - RunAsManager did not change Authentication object
07/04/2020 15:23:12,555  WARN http-nio-8082-exec-9 EntityManagerEnabledFilterAspect:34 - Unable to enable filter
07/04/2020 15:23:12,555  WARN http-nio-8082-exec-9 EntityManagerStoreFilterAspect:41 - Unable to enable filter
07/04/2020 15:23:12,556  WARN http-nio-8082-exec-9 EntityManagerStoreFilterAspect:41 - Unable to enable filter
07/04/2020 15:23:12,613 DEBUG http-nio-8082-exec-9 MethodSecurityInterceptor:219 - Secure object: ReflectiveMethodInvocation: public abstract java.lang.Object com.test.management.repositories.orders.OrderCustomRepository.save(java.lang.Object); target is of class [com.sun.proxy.$Proxy360]; Attributes: [[authorize: &#39;isAuthenticated()&#39;, filter: &#39;null&#39;, filterTarget: &#39;null&#39;]]
07/04/2020 15:23:12,614 DEBUG http-nio-8082-exec-9 AffirmativeBased:66 - Voter: org.springframework.security.access.prepost.PreInvocationAuthorizationAdviceVoter@a3c2c4e, returned: 1
07/04/2020 15:23:12,614 DEBUG http-nio-8082-exec-9 MethodSecurityInterceptor:243 - Authorization successful
07/04/2020 15:23:12,614 DEBUG http-nio-8082-exec-9 MethodSecurityInterceptor:256 - RunAsManager did not change Authentication object
07/04/2020 15:23:12,706 DEBUG http-nio-8082-exec-9 AuditingHandler:173 - Touched Order(super=ManagementAbstractEntity(id=null, sid=null, createdBy=9b9ef528-a45e-4ce9-b014-32a157507aef, createdDate=2020-04-07T13:23:12.705Z, lastModifiedDate=2020-04-07T13:23:12.705Z, lastModifiedBy=9b9ef528-a45e-4ce9-b014-32a157507aef, version=1), tenant=Tenant(type=OPTICIAN, fullName=test, lastName=Rossi, firstName=Daniele, tenantId=pianetatecno, group=earlybird, remoteAddress=null, partnerCode=null, billingAddress=Via Verdi, billingZipCode=45011, billingCity=Milano, billingDistrict=MI, billingCountry=IT, taxCode=null, vatNumber=01234567891, currency=EUR, landlinePhone=+39021234567, mobilePhone=null, fax=null, email=daniele.Rossi@gmail.com, certifiedEmail=null, language=it, iban=null, swift=null, sdiAccountId=AAA1233, leadSource=null, completed=true, verified=true, bankTransferEnabled=true, enabled=true, avatar=false, userAgent=null, lastLogin=2020-04-07T09:43:25.395Z), plan=Plan(super=ManagementAbstractEntity(id=4, sid=9784bd5a-cb02-11e9-a070-0a43c9b616c2, createdBy=system, createdDate=2019-08-30T08:45:55Z, lastModifiedDate=null, lastModifiedBy=null, version=1), planName=Enterprise, group=earlybird, duration=30, validFrom=2019-01-01T00:00:00Z, validUntil=null, type=ENTERPRISE, price=70.00, maxStorageSize=3221225472, minUsers=5, maxUsers=30, minStores=1, maxStores=9, maxContacts=30000, maxDocuments=10000), users=5, stores=2, paymentType=BANK_TRANSFER, paymentDetails=, paymentStatus=PENDING, paymentResult=null, paymentUrl=null, taxRate=22, amount=350.00, taxAmount=77.00, totalAmount=427.00, creditDays=0) - Last modification at 2020-04-07T15:23:12.705 by Optional[9b9ef528-a45e-4ce9-b014-32a157507aef]
07/04/2020 15:23:12,910  INFO myThreadAsync2 OrderCommunicationBuilder:43 - Sending notification email to daniele.Rossi@gmail.com for order eccb87c1-00a9-4fc2-bec0-99025dce665f
07/04/2020 15:23:12,911 DEBUG myThreadAsync2 FreeMarkerUtils:31 - Searching template for emailPendingOrder.ftlh language it
07/04/2020 15:23:12,913 DEBUG myThreadAsync2 SimpleDriverDataSource:142 - Creating new JDBC Driver Connection to [jdbc:h2:mem:testdb]
07/04/2020 15:23:12,914  INFO myThreadAsync2 EmailQueueDispatcher:192 - Enqueue email in AWS outgoing emails for email: Id null To [ daniele.Rossi@gmail.com, daniele.Rossi@gmail.com, info@test.com,  test@gmail.com]
07/04/2020 15:23:12,915  INFO myThreadAsync2 QueueManager:162 - Sending message to the queue EMAIL_OUT_QUEUE
07/04/2020 15:23:12,962 DEBUG myThreadAsync2 QueueManager:173 - Message sent, id: 150da44d-a192-4695-b8ac-85046e4f5256
07/04/2020 15:23:12,984 DEBUG http-nio-8082-exec-9 HttpEntityMethodProcessor:265 - Using &#39;application/json&#39;, given [application/json, text/plain, */*] and supported [application/hal+json, application/json, application/schema+json, application/json-patch+json, application/merge-patch+json, application/x-spring-data-verbose+json, application/x-spring-data-compact+json, application/json, application/json, application/*+json]
07/04/2020 15:23:12,985 DEBUG http-nio-8082-exec-9 HttpEntityMethodProcessor:91 - Writing [Resource { content: Order(super=ManagementAbstractEntity(id=65, sid=eccb87c1-00a9-4fc2-bec0-99025dce (truncated)...]
07/04/2020 15:23:12,985 DEBUG http-nio-8082-exec-9 PersistentEntityJackson2Module:180 - Serializing PersistentEntity org.springframework.data.jpa.mapping.JpaPersistentEntityImpl@bfca966.
07/04/2020 15:23:12,986 DEBUG http-nio-8082-exec-9 HstsHeaderWriter:169 - Not injecting HSTS header since it did not match the requestMatcher org.springframework.security.web.header.writers.HstsHeaderWriter$SecureRequestMatcher@1dc39113
07/04/2020 15:23:12,988 DEBUG http-nio-8082-exec-9 DispatcherServlet:1131 - Completed 200 OK
07/04/2020 15:23:12,988 DEBUG http-nio-8082-exec-9 ExceptionTranslationFilter:120 - Chain processed normally
07/04/2020 15:23:12,988 DEBUG http-nio-8082-exec-9 SecurityContextPersistenceFilter:119 - SecurityContextHolder now cleared, as request processing completed

As you see the code of OrderCommunicationBuilder is executed in a new thread myThreadAsync2. I don't get why TenantController is waiting OrderCommunicationBuilder#sendEmailPendingOrder before return.
Any hint would be appreciated.

huangapple
  • 本文由 发表于 2020年4月7日 21:32:01
  • 转载请务必保留本文链接：https://java.coder-hub.com/61081212.html
匿名

发表评论

匿名网友

:?: :razz: :sad: :evil: :!: :smile: :oops: :grin: :eek: :shock: :???: :cool: :lol: :mad: :twisted: :roll: :wink: :idea: :arrow: :neutral: :cry: :mrgreen:

确定