search

apache / apisix-java-plugin-runner

APISIX Plugin Runner in Java
https://apisix.apache.org/
Apache License 2.0
129 stars 95 forks source link

failed to receive RPC_PREPARE_CONF: timeout #77

Closed ColdFragrance closed 2 years ago

ColdFragrance commented 2 years ago

Issue description

Hi,everyone.According to steps of https://apisix.apache.org/zh/blog/2021/06/21/use-Java-to-write-Apache-APISIX-plugins/，I start java-plugin program and apisix，apisix's log show errors as below:

2021/10/14 19:43:55 [error] 4648#4648: 20111 [lua] init.lua:617: phase_func(): failed to receive RPC_PREPARECONF: timeout, client: 127.0.0.1, server: , request: "GET /get HTTP/1.1", host: "127.0.0.1:9080" 2021/10/14 19:43:55 [warn] 4648#4648: 20111 [lua] plugin.lua:680: runplugin(): ext-plugin-pre-req exits with http status code 503, client: 127.0.0.1, server: , request: "GET /get HTTP/1.1", host: "127.0.0.1:9080"

And description by https://github.com/apache/apisix-java-plugin-runner/blob/release/0.1/docs/en/latest/development.md,I got the same error.

Who can help me？Thanks.

Environment

Dev Environment: CentOS7.4+Eclipse4.21+JDK8+apisix-java-plugin-runner-0.1.0+apisix2.10.0

ColdFragrance commented 2 years ago

The debug log in Eclipse console is:

. _ _ /\ / '_ () \ \ \ \ ( ( )\ | ' | '| | ' \/ ` | \ \ \ \ \/ _)| |)| | | | | || (| | ) ) ) ) ' |__| .|| ||| |\, | / / / / =========|_|==============|__/=//// :: Spring Boot :: (v2.4.5)

2021-10-15 19:42:21.153 INFO 14813 --- [ main] o.a.a.p.r.PluginRunnerApplication : Starting PluginRunnerApplication using Java 1.8.0_191 on localhost.localdomain with PID 14813 (/home/apisix/eclipse-workspace/apisix-java-plugin-runner-main/runner-starter/target/classes started by apisix in /home/apisix/eclipse-workspace/apisix-java-plugin-runner-main/runner-starter) 2021-10-15 19:42:21.170 DEBUG 14813 --- [ main] o.a.a.p.r.PluginRunnerApplication : Running with Spring Boot v2.4.5, Spring v5.3.6 2021-10-15 19:42:21.171 INFO 14813 --- [ main] o.a.a.p.r.PluginRunnerApplication : No active profile set, falling back to default profiles: default 2021-10-15 19:42:21.172 DEBUG 14813 --- [ main] o.s.b.SpringApplication : Loading source class org.apache.apisix.plugin.runner.PluginRunnerApplication 2021-10-15 19:42:21.434 DEBUG 14813 --- [ main] s.c.a.AnnotationConfigApplicationContext : Refreshing org.springframework.context.annotation.AnnotationConfigApplicationContext@61a5b4ae 2021-10-15 19:42:21.520 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'org.springframework.context.annotation.internalConfigurationAnnotationProcessor' 2021-10-15 19:42:21.613 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'org.springframework.boot.autoconfigure.internalCachingMetadataReaderFactory' 2021-10-15 19:42:22.040 DEBUG 14813 --- [ main] o.s.c.a.ClassPathBeanDefinitionScanner : Identified candidate component class: file [/home/apisix/eclipse-workspace/apisix-java-plugin-runner-main/runner-core/target/classes/org/apache/apisix/plugin/runner/codec/PluginRunnerConfiguration.class] 2021-10-15 19:42:22.042 DEBUG 14813 --- [ main] o.s.c.a.ClassPathBeanDefinitionScanner : Identified candidate component class: file [/home/apisix/eclipse-workspace/apisix-java-plugin-runner-main/runner-core/target/classes/org/apache/apisix/plugin/runner/handler/A6HandlerConfiguration.class] 2021-10-15 19:42:22.043 DEBUG 14813 --- [ main] o.s.c.a.ClassPathBeanDefinitionScanner : Identified candidate component class: file [/home/apisix/eclipse-workspace/apisix-java-plugin-runner-main/runner-core/target/classes/org/apache/apisix/plugin/runner/handler/IOHandlerConfiguration.class] 2021-10-15 19:42:22.044 DEBUG 14813 --- [ main] o.s.c.a.ClassPathBeanDefinitionScanner : Identified candidate component class: file [/home/apisix/eclipse-workspace/apisix-java-plugin-runner-main/runner-core/target/classes/org/apache/apisix/plugin/runner/server/ApplicationRunner.class] 2021-10-15 19:42:22.044 DEBUG 14813 --- [ main] o.s.c.a.ClassPathBeanDefinitionScanner : Identified candidate component class: file [/home/apisix/eclipse-workspace/apisix-java-plugin-runner-main/runner-core/target/classes/org/apache/apisix/plugin/runner/server/config/TcpServerConfiguration.class] 2021-10-15 19:42:22.045 DEBUG 14813 --- [ main] o.s.c.a.ClassPathBeanDefinitionScanner : Identified candidate component class: file [/home/apisix/eclipse-workspace/apisix-java-plugin-runner-main/runner-core/target/classes/org/apache/apisix/plugin/runner/service/CacheConfiguration.class] 2021-10-15 19:42:22.045 DEBUG 14813 --- [ main] o.s.c.a.ClassPathBeanDefinitionScanner : Identified candidate component class: file [/home/apisix/eclipse-workspace/apisix-java-plugin-runner-main/runner-plugin/target/classes/org/apache/apisix/plugin/runner/filter/FooFilter.class] 2021-10-15 19:42:22.045 DEBUG 14813 --- [ main] o.s.c.a.ClassPathBeanDefinitionScanner : Identified candidate component class: file [/home/apisix/eclipse-workspace/apisix-java-plugin-runner-main/runner-plugin/target/classes/org/apache/apisix/plugin/runner/filter/TokenValidator.class] 2021-10-15 19:42:23.410 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'propertySourcesPlaceholderConfigurer' 2021-10-15 19:42:23.434 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'org.springframework.context.event.internalEventListenerProcessor' 2021-10-15 19:42:23.470 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'org.springframework.context.event.internalEventListenerFactory' 2021-10-15 19:42:23.474 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'org.springframework.context.annotation.internalAutowiredAnnotationProcessor' 2021-10-15 19:42:23.477 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'org.springframework.context.annotation.internalCommonAnnotationProcessor' 2021-10-15 19:42:23.545 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'org.springframework.boot.context.properties.ConfigurationPropertiesBindingPostProcessor' 2021-10-15 19:42:23.545 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'org.springframework.boot.context.internalConfigurationPropertiesBinder' 2021-10-15 19:42:23.545 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'org.springframework.boot.context.internalConfigurationPropertiesBinderFactory' 2021-10-15 19:42:23.585 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'pluginRunnerApplication' 2021-10-15 19:42:23.621 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'pluginRunnerConfiguration' 2021-10-15 19:42:23.623 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'a6HandlerConfiguration' 2021-10-15 19:42:23.719 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'IOHandlerConfiguration' 2021-10-15 19:42:23.720 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'applicationRunner' 2021-10-15 19:42:23.805 DEBUG 14813 --- [ main] o.s.c.e.PropertySourcesPropertyResolver : Found key 'APISIX_LISTEN_ADDRESS' in PropertySource 'systemEnvironment' with value of type String 2021-10-15 19:42:23.805 DEBUG 14813 --- [ main] o.s.c.e.PropertySourcesPropertyResolver : Found key 'socket.file' in PropertySource 'configurationProperties' with value of type String 2021-10-15 19:42:23.805 DEBUG 14813 --- [ main] o.s.c.e.PropertySourcesPropertyResolver : Found key 'socket.file' in PropertySource 'environmentProperties' with value of type String 2021-10-15 19:42:23.807 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'tcpServerConfiguration' 2021-10-15 19:42:23.808 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'cacheConfiguration' 2021-10-15 19:42:23.809 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'fooFilter' 2021-10-15 19:42:23.843 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'tokenValidator' 2021-10-15 19:42:23.844 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'createDecoder' 2021-10-15 19:42:23.946 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'createEncoder' 2021-10-15 19:42:23.948 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'createConfigHandler' 2021-10-15 19:42:23.979 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'configurationCache' 2021-10-15 19:42:23.980 DEBUG 14813 --- [ main] o.s.c.e.PropertySourcesPropertyResolver : Found key 'APISIX_CONF_EXPIRE_TIME' in PropertySource 'systemEnvironment' with value of type String 2021-10-15 19:42:23.980 DEBUG 14813 --- [ main] o.s.c.e.PropertySourcesPropertyResolver : Found key 'cache.config.expired' in PropertySource 'configurationProperties' with value of type String 2021-10-15 19:42:23.980 DEBUG 14813 --- [ main] o.s.c.e.PropertySourcesPropertyResolver : Found key 'cache.config.expired' in PropertySource 'environmentProperties' with value of type String 2021-10-15 19:42:23.982 DEBUG 14813 --- [ main] o.s.c.e.PropertySourcesPropertyResolver : Found key 'cache.config.capacity' in PropertySource 'configurationProperties' with value of type Integer 2021-10-15 19:42:23.983 DEBUG 14813 --- [ main] o.s.c.e.PropertySourcesPropertyResolver : Found key 'cache.config.capacity' in PropertySource 'environmentProperties' with value of type String 2021-10-15 19:42:24.265 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Autowiring by type from bean name 'createConfigHandler' via factory method to bean named 'configurationCache' Oct 15, 2021 7:42:24 PM org.apache.apisix.plugin.runner.filter.FooFilter name INFO: FooFilter Oct 15, 2021 7:42:24 PM org.apache.apisix.plugin.runner.filter.TokenValidator name INFO: TokenValidator 2021-10-15 19:42:24.314 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'createHttpHandler' 2021-10-15 19:42:24.315 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Autowiring by type from bean name 'createHttpHandler' via factory method to bean named 'configurationCache' 2021-10-15 19:42:24.316 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'createDispatcher' 2021-10-15 19:42:24.317 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Autowiring by type from bean name 'createDispatcher' via factory method to bean named 'createConfigHandler' 2021-10-15 19:42:24.317 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Autowiring by type from bean name 'createDispatcher' via factory method to bean named 'createHttpHandler' 2021-10-15 19:42:24.320 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'createIOHandler' 2021-10-15 19:42:24.321 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Autowiring by type from bean name 'createIOHandler' via factory method to bean named 'createDecoder' 2021-10-15 19:42:24.321 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Autowiring by type from bean name 'createIOHandler' via factory method to bean named 'createDispatcher' 2021-10-15 19:42:24.321 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Autowiring by type from bean name 'createIOHandler' via factory method to bean named 'createEncoder' 2021-10-15 19:42:24.345 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'tcpServer' 2021-10-15 19:42:24.436 DEBUG 14813 --- [ main] r.u.Loggers : Using Slf4j logging framework 2021-10-15 19:42:24.611 DEBUG 14813 --- [ main] i.n.u.i.l.InternalLoggerFactory : Using SLF4J as the default logging framework 2021-10-15 19:42:24.640 DEBUG 14813 --- [ main] i.n.u.i.PlatformDependent0 : -Dio.netty.noUnsafe: false 2021-10-15 19:42:24.641 DEBUG 14813 --- [ main] i.n.u.i.PlatformDependent0 : Java version: 8 2021-10-15 19:42:24.643 DEBUG 14813 --- [ main] i.n.u.i.PlatformDependent0 : sun.misc.Unsafe.theUnsafe: available 2021-10-15 19:42:24.645 DEBUG 14813 --- [ main] i.n.u.i.PlatformDependent0 : sun.misc.Unsafe.copyMemory: available 2021-10-15 19:42:24.645 DEBUG 14813 --- [ main] i.n.u.i.PlatformDependent0 : java.nio.Buffer.address: available 2021-10-15 19:42:24.647 DEBUG 14813 --- [ main] i.n.u.i.PlatformDependent0 : direct buffer constructor: available 2021-10-15 19:42:24.648 DEBUG 14813 --- [ main] i.n.u.i.PlatformDependent0 : java.nio.Bits.unaligned: available, true 2021-10-15 19:42:24.648 DEBUG 14813 --- [ main] i.n.u.i.PlatformDependent0 : jdk.internal.misc.Unsafe.allocateUninitializedArray(int): unavailable prior to Java9 2021-10-15 19:42:24.648 DEBUG 14813 --- [ main] i.n.u.i.PlatformDependent0 : java.nio.DirectByteBuffer.(long, int): available 2021-10-15 19:42:24.648 DEBUG 14813 --- [ main] i.n.u.i.PlatformDependent : sun.misc.Unsafe: available 2021-10-15 19:42:24.649 DEBUG 14813 --- [ main] i.n.u.i.PlatformDependent : -Dio.netty.tmpdir: /tmp (java.io.tmpdir) 2021-10-15 19:42:24.649 DEBUG 14813 --- [ main] i.n.u.i.PlatformDependent : -Dio.netty.bitMode: 64 (sun.arch.data.model) 2021-10-15 19:42:24.694 DEBUG 14813 --- [ main] i.n.u.i.PlatformDependent : -Dio.netty.maxDirectMemory: 1380581376 bytes 2021-10-15 19:42:24.695 DEBUG 14813 --- [ main] i.n.u.i.PlatformDependent : -Dio.netty.uninitializedArrayAllocationThreshold: -1 2021-10-15 19:42:24.697 DEBUG 14813 --- [ main] i.n.u.i.CleanerJava6 : java.nio.ByteBuffer.cleaner(): available 2021-10-15 19:42:24.697 DEBUG 14813 --- [ main] i.n.u.i.PlatformDependent : -Dio.netty.noPreferDirect: false 2021-10-15 19:42:24.933 DEBUG 14813 --- [ main] i.n.u.ResourceLeakDetector : -Dio.netty.leakDetection.level: simple 2021-10-15 19:42:24.934 DEBUG 14813 --- [ main] i.n.u.ResourceLeakDetector : -Dio.netty.leakDetection.targetRecords: 4 2021-10-15 19:42:25.037 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'org.springframework.boot.autoconfigure.AutoConfigurationPackages' 2021-10-15 19:42:25.038 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'org.springframework.boot.autoconfigure.context.PropertyPlaceholderAutoConfiguration' 2021-10-15 19:42:25.039 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'org.springframework.boot.autoconfigure.aop.AopAutoConfiguration$ClassProxyingConfiguration' 2021-10-15 19:42:25.067 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Autowiring by type from bean name 'org.springframework.boot.autoconfigure.aop.AopAutoConfiguration$ClassProxyingConfiguration' via constructor to bean named 'org.springframework.beans.factory.support.DefaultListableBeanFactory@69eb86b4' 2021-10-15 19:42:25.106 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'org.springframework.boot.autoconfigure.aop.AopAutoConfiguration' 2021-10-15 19:42:25.107 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'org.springframework.boot.autoconfigure.availability.ApplicationAvailabilityAutoConfiguration' 2021-10-15 19:42:25.108 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'applicationAvailability' 2021-10-15 19:42:25.110 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'org.springframework.boot.autoconfigure.context.ConfigurationPropertiesAutoConfiguration' 2021-10-15 19:42:25.141 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'org.springframework.boot.context.properties.BoundConfigurationProperties' 2021-10-15 19:42:25.141 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'org.springframework.boot.context.properties.EnableConfigurationPropertiesRegistrar.methodValidationExcludeFilter' 2021-10-15 19:42:25.176 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'org.springframework.boot.autoconfigure.context.LifecycleAutoConfiguration' 2021-10-15 19:42:25.177 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'lifecycleProcessor' 2021-10-15 19:42:25.177 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'spring.lifecycle-org.springframework.boot.autoconfigure.context.LifecycleProperties' 2021-10-15 19:42:25.344 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Autowiring by type from bean name 'lifecycleProcessor' via factory method to bean named 'spring.lifecycle-org.springframework.boot.autoconfigure.context.LifecycleProperties' 2021-10-15 19:42:25.348 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'org.springframework.boot.autoconfigure.gson.GsonAutoConfiguration' 2021-10-15 19:42:25.350 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'gsonBuilder' 2021-10-15 19:42:25.351 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'standardGsonBuilderCustomizer' 2021-10-15 19:42:25.351 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'spring.gson-org.springframework.boot.autoconfigure.gson.GsonProperties' 2021-10-15 19:42:25.388 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Autowiring by type from bean name 'standardGsonBuilderCustomizer' via factory method to bean named 'spring.gson-org.springframework.boot.autoconfigure.gson.GsonProperties' 2021-10-15 19:42:25.390 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Autowiring by type from bean name 'gsonBuilder' via factory method to bean named 'standardGsonBuilderCustomizer' 2021-10-15 19:42:25.499 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'gson' 2021-10-15 19:42:25.525 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Autowiring by type from bean name 'gson' via factory method to bean named 'gsonBuilder' 2021-10-15 19:42:25.775 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'org.springframework.boot.autoconfigure.info.ProjectInfoAutoConfiguration' 2021-10-15 19:42:25.796 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'spring.info-org.springframework.boot.autoconfigure.info.ProjectInfoProperties' 2021-10-15 19:42:25.799 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Autowiring by type from bean name 'org.springframework.boot.autoconfigure.info.ProjectInfoAutoConfiguration' via constructor to bean named 'spring.info-org.springframework.boot.autoconfigure.info.ProjectInfoProperties' 2021-10-15 19:42:25.799 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'org.springframework.boot.autoconfigure.task.TaskExecutionAutoConfiguration' 2021-10-15 19:42:25.800 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'taskExecutorBuilder' 2021-10-15 19:42:25.841 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'spring.task.execution-org.springframework.boot.autoconfigure.task.TaskExecutionProperties' 2021-10-15 19:42:25.844 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Autowiring by type from bean name 'taskExecutorBuilder' via factory method to bean named 'spring.task.execution-org.springframework.boot.autoconfigure.task.TaskExecutionProperties' 2021-10-15 19:42:25.847 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'org.springframework.boot.autoconfigure.task.TaskSchedulingAutoConfiguration' 2021-10-15 19:42:25.879 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'taskSchedulerBuilder' 2021-10-15 19:42:25.880 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Creating shared instance of singleton bean 'spring.task.scheduling-org.springframework.boot.autoconfigure.task.TaskSchedulingProperties' 2021-10-15 19:42:25.883 DEBUG 14813 --- [ main] o.s.b.f.s.DefaultListableBeanFactory : Autowiring by type from bean name 'taskSchedulerBuilder' via factory method to bean named 'spring.task.scheduling-org.springframework.boot.autoconfigure.task.TaskSchedulingProperties' 2021-10-15 19:42:26.108 DEBUG 14813 --- [ main] ConditionEvaluationReportLoggingListener :

============================ CONDITIONS EVALUATION REPORT

Positive matches:

AopAutoConfiguration matched:

Negative matches:

ActiveMQAutoConfiguration: Did not match:

Exclusions:

None

Unconditional classes:

org.springframework.boot.autoconfigure.context.ConfigurationPropertiesAutoConfiguration

org.springframework.boot.autoconfigure.context.LifecycleAutoConfiguration

org.springframework.boot.autoconfigure.context.PropertyPlaceholderAutoConfiguration

org.springframework.boot.autoconfigure.availability.ApplicationAvailabilityAutoConfiguration

org.springframework.boot.autoconfigure.info.ProjectInfoAutoConfiguration

2021-10-15 19:42:26.162 INFO 14813 --- [ main] o.a.a.p.r.PluginRunnerApplication : Started PluginRunnerApplication in 7.225 seconds (JVM running for 11.012) 2021-10-15 19:42:26.559 DEBUG 14813 --- [ main] r.n.t.TcpResources : [tcp] resources will use the default LoopResources: DefaultLoopResources {prefix=reactor-tcp, daemon=true, selectCount=4, workerCount=4} 2021-10-15 19:42:26.559 DEBUG 14813 --- [ main] r.n.t.TcpResources : [tcp] resources will use the default ConnectionProvider: reactor.netty.resources.DefaultPooledConnectionProvider@7e7f3cfd 2021-10-15 19:42:26.578 DEBUG 14813 --- [ main] r.n.r.DefaultLoopIOUring : Default io_uring support : false 2021-10-15 19:42:26.592 DEBUG 14813 --- [ main] i.n.u.i.NativeLibraryLoader : -Dio.netty.native.workdir: /tmp (io.netty.tmpdir) 2021-10-15 19:42:26.592 DEBUG 14813 --- [ main] i.n.u.i.NativeLibraryLoader : -Dio.netty.native.deleteLibAfterLoading: true 2021-10-15 19:42:26.592 DEBUG 14813 --- [ main] i.n.u.i.NativeLibraryLoader : -Dio.netty.native.tryPatchShadedId: true 2021-10-15 19:42:26.650 DEBUG 14813 --- [ main] i.n.u.i.NativeLibraryLoader : Successfully loaded the library /tmp/libnetty_transport_native_epoll_x86_642397306612351315684.so 2021-10-15 19:42:26.689 DEBUG 14813 --- [ main] i.n.u.NetUtil : -Djava.net.preferIPv4Stack: false 2021-10-15 19:42:26.689 DEBUG 14813 --- [ main] i.n.u.NetUtil : -Djava.net.preferIPv6Addresses: false 2021-10-15 19:42:26.692 DEBUG 14813 --- [ main] i.n.u.NetUtilInitializations : Loopback interface: lo (lo, 0:0:0:0:0:0:0:1%lo) 2021-10-15 19:42:26.741 DEBUG 14813 --- [ main] i.n.u.NetUtil : /proc/sys/net/core/somaxconn: 128 2021-10-15 19:42:26.742 DEBUG 14813 --- [ main] r.n.r.DefaultLoopEpoll : Default Epoll support : true 2021-10-15 19:42:26.751 DEBUG 14813 --- [ main] i.n.c.MultithreadEventLoopGroup : -Dio.netty.eventLoopThreads: 2 2021-10-15 19:42:26.849 DEBUG 14813 --- [ main] i.n.u.i.InternalThreadLocalMap : -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024 2021-10-15 19:42:26.850 DEBUG 14813 --- [ main] i.n.u.i.InternalThreadLocalMap : -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096 2021-10-15 19:42:26.933 DEBUG 14813 --- [ main] i.n.u.i.PlatformDependent : org.jctools-core.MpscChunkedArrayQueue: available 2021-10-15 19:42:27.060 DEBUG 14813 --- [ main] i.n.c.DefaultChannelId : -Dio.netty.processId: 14813 (auto-detected) 2021-10-15 19:42:27.097 DEBUG 14813 --- [ main] i.n.c.DefaultChannelId : -Dio.netty.machineId: 00:0c:29:ff:fe:71:ec:77 (auto-detected) 2021-10-15 19:42:27.232 DEBUG 14813 --- [ main] i.n.b.PooledByteBufAllocator : -Dio.netty.allocator.numHeapArenas: 2 2021-10-15 19:42:27.232 DEBUG 14813 --- [ main] i.n.b.PooledByteBufAllocator : -Dio.netty.allocator.numDirectArenas: 2 2021-10-15 19:42:27.232 DEBUG 14813 --- [ main] i.n.b.PooledByteBufAllocator : -Dio.netty.allocator.pageSize: 8192 2021-10-15 19:42:27.232 DEBUG 14813 --- [ main] i.n.b.PooledByteBufAllocator : -Dio.netty.allocator.maxOrder: 11 2021-10-15 19:42:27.232 DEBUG 14813 --- [ main] i.n.b.PooledByteBufAllocator : -Dio.netty.allocator.chunkSize: 16777216 2021-10-15 19:42:27.232 DEBUG 14813 --- [ main] i.n.b.PooledByteBufAllocator : -Dio.netty.allocator.smallCacheSize: 256 2021-10-15 19:42:27.232 DEBUG 14813 --- [ main] i.n.b.PooledByteBufAllocator : -Dio.netty.allocator.normalCacheSize: 64 2021-10-15 19:42:27.233 DEBUG 14813 --- [ main] i.n.b.PooledByteBufAllocator : -Dio.netty.allocator.maxCachedBufferCapacity: 32768 2021-10-15 19:42:27.233 DEBUG 14813 --- [ main] i.n.b.PooledByteBufAllocator : -Dio.netty.allocator.cacheTrimInterval: 8192 2021-10-15 19:42:27.233 DEBUG 14813 --- [ main] i.n.b.PooledByteBufAllocator : -Dio.netty.allocator.cacheTrimIntervalMillis: 0 2021-10-15 19:42:27.233 DEBUG 14813 --- [ main] i.n.b.PooledByteBufAllocator : -Dio.netty.allocator.useCacheForAllThreads: true 2021-10-15 19:42:27.272 DEBUG 14813 --- [ main] i.n.b.PooledByteBufAllocator : -Dio.netty.allocator.maxCachedByteBuffersPerChunk: 1023 2021-10-15 19:42:27.317 DEBUG 14813 --- [ main] i.n.b.ByteBufUtil : -Dio.netty.allocator.type: pooled 2021-10-15 19:42:27.317 DEBUG 14813 --- [ main] i.n.b.ByteBufUtil : -Dio.netty.threadLocalDirectBufferSize: 0 2021-10-15 19:42:27.317 DEBUG 14813 --- [ main] i.n.b.ByteBufUtil : -Dio.netty.maxThreadLocalCharBufferSize: 16384 2021-10-15 19:42:27.799 DEBUG 14813 --- [tor-tcp-epoll-1] r.n.t.ServerTransport : [id:6d696b47, L:/tmp/runner.sock] Bound new server 2021-10-15 19:42:27.803 WARN 14813 --- [ main] o.a.a.p.r.s.ApplicationRunner : java runner is listening on the socket file: /tmp/runner.sock 2021-10-15 19:42:47.272 DEBUG 14813 --- [tor-tcp-epoll-2] r.n.t.TransportConfig : [id:cc52b1d8] Initialized pipeline DefaultChannelPipeline{(logger = io.netty.handler.logging.LoggingHandler), (delayedDecoder = org.apache.apisix.plugin.runner.codec.DelayedDecoder), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)} 2021-10-15 19:42:47.291 DEBUG 14813 --- [tor-tcp-epoll-2] i.n.h.l.LoggingHandler : [id: 0xcc52b1d8] REGISTERED 2021-10-15 19:42:47.291 DEBUG 14813 --- [tor-tcp-epoll-2] i.n.h.l.LoggingHandler : [id: 0xcc52b1d8] ACTIVE 2021-10-15 19:42:47.303 DEBUG 14813 --- [tor-tcp-epoll-3] r.n.t.TransportConfig : [id:0f2c7754] Initialized pipeline DefaultChannelPipeline{(logger = io.netty.handler.logging.LoggingHandler), (delayedDecoder = org.apache.apisix.plugin.runner.codec.DelayedDecoder), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)} 2021-10-15 19:42:47.304 DEBUG 14813 --- [tor-tcp-epoll-3] i.n.h.l.LoggingHandler : [id: 0x0f2c7754] REGISTERED 2021-10-15 19:42:47.304 DEBUG 14813 --- [tor-tcp-epoll-3] i.n.h.l.LoggingHandler : [id: 0x0f2c7754] ACTIVE 2021-10-15 19:43:47.250 DEBUG 14813 --- [tor-tcp-epoll-3] i.n.u.Recycler : -Dio.netty.recycler.maxCapacityPerThread: 4096 2021-10-15 19:43:47.250 DEBUG 14813 --- [tor-tcp-epoll-3] i.n.u.Recycler : -Dio.netty.recycler.maxSharedCapacityFactor: 2 2021-10-15 19:43:47.250 DEBUG 14813 --- [tor-tcp-epoll-3] i.n.u.Recycler : -Dio.netty.recycler.linkCapacity: 16 2021-10-15 19:43:47.250 DEBUG 14813 --- [tor-tcp-epoll-3] i.n.u.Recycler : -Dio.netty.recycler.ratio: 8 2021-10-15 19:43:47.250 DEBUG 14813 --- [tor-tcp-epoll-3] i.n.u.Recycler : -Dio.netty.recycler.delayedQueue.ratio: 8 2021-10-15 19:43:47.271 DEBUG 14813 --- [tor-tcp-epoll-3] i.n.b.AbstractByteBuf : -Dio.netty.buffer.checkAccessible: true 2021-10-15 19:43:47.271 DEBUG 14813 --- [tor-tcp-epoll-3] i.n.b.AbstractByteBuf : -Dio.netty.buffer.checkBounds: true 2021-10-15 19:43:47.272 DEBUG 14813 --- [tor-tcp-epoll-3] i.n.u.ResourceLeakDetectorFactory : Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@11042ff5 2021-10-15 19:43:47.281 DEBUG 14813 --- [tor-tcp-epoll-2] i.n.h.l.LoggingHandler : [id: 0xcc52b1d8] READ COMPLETE 2021-10-15 19:43:47.283 DEBUG 14813 --- [tor-tcp-epoll-2] i.n.h.l.LoggingHandler : [id: 0xcc52b1d8] INACTIVE 2021-10-15 19:43:47.286 DEBUG 14813 --- [tor-tcp-epoll-2] i.n.h.l.LoggingHandler : [id: 0xcc52b1d8] UNREGISTERED 2021-10-15 19:43:47.288 DEBUG 14813 --- [tor-tcp-epoll-3] i.n.h.l.LoggingHandler : [id: 0x0f2c7754] READ: 116B +-------------------------------------------------+ | 0 1 2 3 4 5 6 7 8 9 a b c d e f | +--------+-------------------------------------------------+----------------+ |00000000| 01 00 00 70 0c 00 00 00 08 00 0c 00 04 00 08 00 |...p............| |00000010| 08 00 00 00 08 00 00 00 38 00 00 00 01 00 00 00 |........8.......| |00000020| 0c 00 00 00 08 00 0c 00 08 00 04 00 08 00 00 00 |................| |00000030| 08 00 00 00 0c 00 00 00 03 00 00 00 62 61 72 00 |............bar.| |00000040| 09 00 00 00 46 6f 6f 46 69 6c 74 65 72 00 00 00 |....FooFilter...| |00000050| 1e 00 00 00 72 6f 75 74 65 23 31 23 65 78 74 2d |....route#1#ext-| |00000060| 70 6c 75 67 69 6e 2d 70 72 65 2d 72 65 71 23 35 |plugin-pre-req#5| |00000070| 37 31 00 00 |71.. | +--------+-------------------------------------------------+----------------+ 2021-10-15 19:43:47.291 DEBUG 14813 --- [tor-tcp-epoll-3] i.n.h.l.LoggingHandler : [id: 0x0f2c7754] READ COMPLETE 2021-10-15 19:43:47.292 DEBUG 14813 --- [tor-tcp-epoll-3] i.n.h.l.LoggingHandler : [id: 0x0f2c7754] READ COMPLETE 2021-10-15 19:43:47.292 DEBUG 14813 --- [tor-tcp-epoll-3] i.n.h.l.LoggingHandler : [id: 0x0f2c7754] INACTIVE 2021-10-15 19:43:47.292 DEBUG 14813 --- [tor-tcp-epoll-3] r.n.c.FluxReceive : [id:0f2c7754] FluxReceive{pending=0, cancelled=true, inboundDone=false, inboundError=null}: dropping frame PooledSlicedByteBuf(ridx: 0, widx: 116, cap: 116/116, unwrapped: PooledUnsafeDirectByteBuf(ridx: 116, widx: 116, cap: 2048)) 2021-10-15 19:43:47.292 DEBUG 14813 --- [tor-tcp-epoll-3] i.n.h.l.LoggingHandler : [id: 0x0f2c7754] UNREGISTERED

tzssangglass commented 2 years ago

java runner is listening on the socket file: /tmp/runner.sock

What is the address of path_for_test in apisix? refer to:https://github.com/apache/apisix/blob/064af069ab721221000e32c189b655f2d6456993/docs/en/latest/external-plugin.md#configuration-for-plugin-runner-in-apisix

tzssangglass commented 2 years ago

And you can use the master branch to test.

It looks like the java plugin runner has received the request form APISIX.

2021-10-15 19:43:47.292 DEBUG 14813 --- [tor-tcp-epoll-3] i.n.h.l.LoggingHandler : [id: 0x0f2c7754] INACTIVE 2021-10-15 19:43:47.292 DEBUG 14813 --- [tor-tcp-epoll-3] r.n.c.FluxReceive : [id:0f2c7754] FluxReceive{pending=0, cancelled=true, inboundDone=false, inboundError=null}: dropping frame PooledSlicedByteBuf(ridx: 0, widx: 116, cap: 116/116, unwrapped: PooledUnsafeDirectByteBuf(ridx: 116, widx: 116, cap: 2048)) 2021-10-15 19:43:47.292 DEBUG 14813 --- [tor-tcp-epoll-3] i.n.h.l.LoggingHandler : [id: 0x0f2c7754] UNREGISTERED

see if there are any problems with these logs.

And did you break the point in the java plugin code?

ColdFragrance commented 2 years ago

I used the master branch.and no breakpoint all the time.

ColdFragrance commented 2 years ago

My plugin's code as below: package org.apache.apisix.plugin.runner.filter;

import java.util.logging.Logger;

import org.apache.apisix.plugin.runner.HttpRequest; import org.apache.apisix.plugin.runner.HttpResponse; import org.springframework.stereotype.Component;

import reactor.core.publisher.Mono;

@Component public class FooFilter implements PluginFilter {

private static final Logger log4j = Logger.getLogger("FooFilter");

@Override
public String name() {
    log4j.info("FooFilter");
    return "FooFilter";
}

@Override
public Mono<Void> filter(HttpRequest request, HttpResponse response, PluginFilterChain chain) {
    log4j.info("FooFilter filter");
    return chain.filter(request, response);
}

}

Additionally, my test via curl is normal when non-java-plugin.

tzssangglass commented 2 years ago

I cannot reproduce this error.

And where do you put your code? see;https://github.com/apache/apisix-java-plugin-runner/blob/main/docs/en/latest/development.md#code-location

ColdFragrance commented 2 years ago

My code is put in apisix-runner-plugin project as the image as below.

image

tzssangglass commented 2 years ago

The code position is correct, but I can't reproduce the error.

ColdFragrance commented 2 years ago

Er，what shall I do now？

tzssangglass commented 2 years ago

Maybe you can try run mode:https://github.com/apache/apisix-java-plugin-runner/blob/main/docs/en/latest/how-it-works.md#run

ColdFragrance commented 2 years ago

@tzssangglass My platform is Windows7+VMWare15 Pro+CentOS7.4+Eclipse4.21+JDK8. What's yours?Is this relevant?

tzssangglass commented 2 years ago

@tzssangglass My platform is Windows7+VMWare15 Pro+CentOS7.4+Eclipse4.21+JDK8. What's yours?Is this relevant?

I'm developing in Centos7.5. Iguess the env is ok, because I see that the request has send to the plugin in logs. maybe yo need to focus on the java code.

ColdFragrance commented 2 years ago

My java code is from https://apisix.apache.org/zh/blog/2021/06/21/use-Java-to-write-Apache-APISIX-plugins/ and https://github.com/apache/apisix-java-plugin-runner/blob/release/0.1/docs/en/latest/development.md.The code and its location is mentioned as above.

ColdFragrance commented 2 years ago

This is the log in apisix as run mode. image

tzssangglass commented 2 years ago

see: https://github.com/apache/apisix-java-plugin-runner/blob/feac0530a29a51a70acf7120e4059e8bf4dc9f4b/runner-core/src/test/java/org/apache/apisix/plugin/runner/handler/A6ConfigHandlerTest.java#L157-L177

this means that your filter is not injected into the filter chain.

how to fix: https://github.com/apache/apisix-java-plugin-runner/blob/main/docs/en/latest/development.md#the-name-of-filter-execution

tzssangglass commented 2 years ago

no more response, considered as resolved, feel free to reopen this.

jiuchongxiao commented 2 years ago

@ColdFragrance do you solved it ,how to solved? i have the same issue

ennian001 commented 2 years ago

no more response, considered as resolved, feel free to reopen this. @ColdFragrance do you solved it ,how to solved? i have the same issue

1075924135 commented 1 year ago

1.8不支持0.4.0中的语法，linux上把jdk替换成11执行，问题解决