fail to execute simple shell task in 1.39 release standalone mode #7323

RedemptionC · 2021-12-10T09:21:33Z

RedemptionC
Dec 10, 2021

I'm trying to run a simple shell task:

And it fails,why?

the log from console:

2021-12-10 17:07:18.500  INFO 100826 --- [p2057104863-201] o.a.d.a.c.ProcessDefinitionController    : query process definition list paging, login user:admin, project name:pj_001
2021-12-10 17:07:25.396  INFO 100826 --- [p2057104863-185] o.a.d.a.c.WorkerGroupController          : query all worker group: login user admin
2021-12-10 17:07:25.396  INFO 100826 --- [p2057104863-200] o.a.d.api.controller.ExecutorController  : login user admin, check process definition 1
2021-12-10 17:07:25.421  INFO 100826 --- [tp2057104863-66] o.a.d.api.controller.ExecutorController  : login user admin, get process definition receiver and cc
2021-12-10 17:07:25.421  INFO 100826 --- [tp2057104863-66] o.a.d.api.service.ExecutorService        : processInstanceId null
2021-12-10 17:07:27.168  INFO 100826 --- [p2057104863-176] o.a.d.api.controller.ExecutorController  : login user admin, start process instance, project name: pj_001, process definition id: 1, schedule time: , failure policy: CONTINUE, node name: , node dep: TASK_POST, notify type: NONE, notify group id: default,receivers:,receiversCc:, run mode: RUN_MODE_SERIAL,process instance priority:MEDIUM, workerGroup: default, timeout: null
2021-12-10 17:07:27.281  INFO 100826 --- [p2057104863-179] o.a.d.a.c.ProcessDefinitionController    : query process definition list paging, login user:admin, project name:pj_001
2021-12-10 17:07:27.797  INFO 100826 --- [SchedulerThread] o.a.d.s.m.runner.MasterSchedulerService  : find one command: id: 2, type: START_PROCESS
2021-12-10 17:07:27.800  INFO 100826 --- [SchedulerThread] o.a.d.s.m.runner.MasterSchedulerService  : start master exec thread , split DAG ...
2021-12-10 17:07:27.801  INFO 100826 --- [ter-Exec-Thread] o.a.d.s.master.runner.MasterExecThread   : prepare process :2 end
2021-12-10 17:07:27.802  INFO 100826 --- [ter-Exec-Thread] o.a.d.s.master.runner.MasterExecThread   : add task to stand by list: shell_001
2021-12-10 17:07:27.804  INFO 100826 --- [ter-Exec-Thread] o.a.d.s.master.runner.MasterExecThread   : remove task from stand by list: shell_001
2021-12-10 17:07:27.805  INFO 100826 --- [ask-Exec-Thread] o.a.d.service.process.ProcessService     : start submit task : shell_001, instance id:2, state: RUNNING_EXECUTION
2021-12-10 17:07:27.807  INFO 100826 --- [ask-Exec-Thread] o.a.d.service.process.ProcessService     : end submit task to db successfully:shell_001 state:SUBMITTED_SUCCESS complete, instance id:2 state: RUNNING_EXECUTION  
2021-12-10 17:07:27.807  INFO 100826 --- [ask-Exec-Thread] o.a.d.s.m.runner.MasterTaskExecThread    : task ready to submit: TaskInstance{id=2, name='shell_001', taskType='SHELL', processDefinitionId=1, processInstanceId=2, processInstanceName='null', taskJson='{"conditionResult":"{\"successNode\":[\"\"],\"failedNode\":[\"\"]}","conditionsTask":false,"depList":[],"dependence":"{}","forbidden":false,"id":"tasks-63322","maxRetryTimes":0,"name":"shell_001","params":"{\"rawScript\":\"echo \\\"shell task in dolphinscheduler begin\\\"\\necho \\\"$name shell task in dolphinscheduler running\\\"\\necho \\\"shell task in dolphinscheduler end\\\"\\n\",\"localParams\":[{\"prop\":\"name\",\"direct\":\"IN\",\"type\":\"VARCHAR\",\"value\":\"red\"}],\"resourceList\":[]}","preTasks":"[]","retryInterval":1,"runFlag":"NORMAL","taskInstancePriority":"MEDIUM","taskTimeoutParameter":{"enable":false,"interval":0},"timeout":"{\"enable\":false,\"strategy\":\"\"}","type":"SHELL","workerGroup":"default"}', state=SUBMITTED_SUCCESS, submitTime=Fri Dec 10 17:07:27 CST 2021, startTime=null, endTime=null, host='null', executePath='null', logPath='null', retryTimes=0, alertFlag=NO, processInstance=null, processDefine=null, pid=0, appLink='null', flag=YES, dependency='null', duration=null, maxRetryTimes=0, retryInterval=1, taskInstancePriority=MEDIUM, processInstancePriority=MEDIUM, dependentResult='null', workerGroup='default', executorId=1, executorName='null'}
2021-12-10 17:07:27.807  INFO 100826 --- [ask-Exec-Thread] o.a.d.s.m.runner.MasterTaskExecThread    : master submit success, task : shell_001
2021-12-10 17:07:27.808  INFO 100826 --- [ask-Exec-Thread] o.a.d.s.m.runner.MasterTaskExecThread    : wait task: process id: 2, task id:2, task name:shell_001 complete
2021-12-10 17:07:27.884  INFO 100826 --- [ool-13-thread-2] o.a.d.s.w.p.TaskExecuteProcessor         : received command : TaskExecuteRequestCommand{taskExecutionContext='{"cmdTypeIfComplement":0,"dataxTaskExecutionContext":{"dataSourceId":0,"dataTargetId":0,"sourcetype":0,"targetType":0},"executorId":1,"procedureTaskExecutionContext":{},"processDefineId":1,"processId":0,"processInstanceId":2,"projectId":1,"queue":"default","resources":{},"sqlTaskExecutionContext":{"warningGroupId":0},"sqoopTaskExecutionContext":{"dataSourceId":0,"dataTargetId":0,"sourcetype":0,"targetType":0},"taskInstanceId":2,"taskJson":"{\"conditionResult\":\"{\\\"successNode\\\":[\\\"\\\"],\\\"failedNode\\\":[\\\"\\\"]}\",\"conditionsTask\":false,\"depList\":[],\"dependence\":\"{}\",\"forbidden\":false,\"id\":\"tasks-63322\",\"maxRetryTimes\":0,\"name\":\"shell_001\",\"params\":\"{\\\"rawScript\\\":\\\"echo \\\\\\\"shell task in dolphinscheduler begin\\\\\\\"\\\\necho \\\\\\\"$name shell task in dolphinscheduler running\\\\\\\"\\\\necho \\\\\\\"shell task in dolphinscheduler end\\\\\\\"\\\\n\\\",\\\"localParams\\\":[{\\\"prop\\\":\\\"name\\\",\\\"direct\\\":\\\"IN\\\",\\\"type\\\":\\\"VARCHAR\\\",\\\"value\\\":\\\"red\\\"}],\\\"resourceList\\\":[]}\",\"preTasks\":\"[]\",\"retryInterval\":1,\"runFlag\":\"NORMAL\",\"taskInstancePriority\":\"MEDIUM\",\"taskTimeoutParameter\":{\"enable\":false,\"interval\":0},\"timeout\":\"{\\\"enable\\\":false,\\\"strategy\\\":\\\"\\\"}\",\"type\":\"SHELL\",\"workerGroup\":\"default\"}","taskName":"shell_001","taskTimeout":0,"taskTimeoutStrategy":0,"taskType":"SHELL","tenantCode":"tenant_001","workerGroup":"default"}'}
2021-12-10 17:07:27.884 ERROR 100826 --- [ool-13-thread-2] o.a.d.remote.handler.NettyServerHandler  : process msg Command [type=TASK_EXECUTE_REQUEST, opaque=3, bodyLen=1904] error

java.lang.NullPointerException: null
	at org.apache.dolphinscheduler.server.worker.processor.TaskExecuteProcessor.getTaskLogPath(TaskExecuteProcessor.java:175) ~[classes/:na]
	at org.apache.dolphinscheduler.server.worker.processor.TaskExecuteProcessor.process(TaskExecuteProcessor.java:133) ~[classes/:na]
	at org.apache.dolphinscheduler.remote.handler.NettyServerHandler$1.run(NettyServerHandler.java:134) ~[classes/:na]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_291]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_291]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_291]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_291]
	at java.lang.Thread.run(Thread.java:748) [na:1.8.0_291]

Answered by RedemptionC

Dec 13, 2021

It can be seen from the printed log that the logback-standalone.xml log configuration is not used, please add -Dlogging.config=classpath:logback-standalone.xml JVM parameter when starting standalone

Yes , this is the answer

View full answer

Lucaszlei · 2021-12-10T11:53:17Z

Lucaszlei
Dec 10, 2021

Have you changed the configuration file of the log, and you cannot obtain the log-related configuration during the execution of the task, resulting in a null pointer exception

Corresponding to the log file logback-worker.xml

1 reply

RedemptionC Dec 10, 2021
Author

Hello,thanks for your reply
But I didn't change that:https://github.com/apache/dolphinscheduler/blob/1.3.9-release/dolphinscheduler-standalone-server/src/main/resources/logback-standalone.xml

RedemptionC · 2021-12-11T06:32:24Z

RedemptionC
Dec 11, 2021
Author

I debugged and found that getLogger("Root") works fine,but when I try getting appender,it only gets Null

0 replies

RedemptionC · 2021-12-11T12:13:40Z

RedemptionC
Dec 11, 2021
Author

Also,I tried standalone mode in dev branch,also failed to run:

2021-12-11 20:12:05.286  INFO 204909 --- [tp153950082-149] o.a.d.s.c.impl.CacheNotifyServiceImpl    : send result, command:Command [type=CACHE_EXPIRE, opaque=31, bodyLen=61]
2021-12-11 20:12:05.289  INFO 204909 --- [pool-7-thread-2] o.a.d.s.master.processor.CacheProcessor  : received command : CacheExpireCommand{CacheType=PROCESS_DEFINITION, cacheKey=3813662028512}
2021-12-11 20:12:05.289  INFO 204909 --- [pool-7-thread-2] o.a.d.s.master.processor.CacheProcessor  : cache evict, type:processDefinition, key:3813662028512
2021-12-11 20:12:05.289 ERROR 204909 --- [tp153950082-149] o.a.d.a.exceptions.ApiExceptionHandler   : 上线工作流错误

org.springframework.expression.spel.SpelEvaluationException: EL1007E: Property or field 'code' cannot be found on null
	at org.springframework.expression.spel.ast.PropertyOrFieldReference.readProperty(PropertyOrFieldReference.java:213) ~[spring-expression-5.3.12.jar:5.3.12]
	at org.springframework.expression.spel.ast.PropertyOrFieldReference.getValueInternal(PropertyOrFieldReference.java:104) ~[spring-expression-5.3.12.jar:5.3.12]
	at org.springframework.expression.spel.ast.PropertyOrFieldReference.access$000(PropertyOrFieldReference.java:51) ~[spring-expression-5.3.12.jar:5.3.12]
	at org.springframework.expression.spel.ast.PropertyOrFieldReference$AccessorLValue.getValue(PropertyOrFieldReference.java:406) ~[spring-expression-5.3.12.jar:5.3.12]
	at org.springframework.expression.spel.ast.CompoundExpression.getValueInternal(CompoundExpression.java:92) ~[spring-expression-5.3.12.jar:5.3.12]
	at org.springframework.expression.spel.ast.SpelNodeImpl.getValue(SpelNodeImpl.java:112) ~[spring-expression-5.3.12.jar:5.3.12]
	at org.springframework.expression.spel.standard.SpelExpression.getValue(SpelExpression.java:272) ~[spring-expression-5.3.12.jar:5.3.12]
	at org.springframework.cache.interceptor.CacheOperationExpressionEvaluator.key(CacheOperationExpressionEvaluator.java:104) ~[spring-context-5.3.12.jar:5.3.12]
	at org.springframework.cache.interceptor.CacheAspectSupport$CacheOperationContext.generateKey(CacheAspectSupport.java:795) ~[spring-context-5.3.12.jar:5.3.12]
	at org.springframework.cache.interceptor.CacheAspectSupport.generateKey(CacheAspectSupport.java:592) ~[spring-context-5.3.12.jar:5.3.12]
	at org.springframework.cache.interceptor.CacheAspectSupport.performCacheEvict(CacheAspectSupport.java:509) ~[spring-context-5.3.12.jar:5.3.12]
	at org.springframework.cache.interceptor.CacheAspectSupport.processCacheEvicts(CacheAspectSupport.java:493) ~[spring-context-5.3.12.jar:5.3.12]
	at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:434) ~[spring-context-5.3.12.jar:5.3.12]
	at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:345) ~[spring-context-5.3.12.jar:5.3.12]
	at org.springframework.cache.interceptor.CacheInterceptor.invoke(CacheInterceptor.java:64) ~[spring-context-5.3.12.jar:5.3.12]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.12.jar:5.3.12]
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97) ~[spring-aop-5.3.12.jar:5.3.12]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.12.jar:5.3.12]
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:215) ~[spring-aop-5.3.12.jar:5.3.12]
	at com.sun.proxy.$Proxy120.updateById(Unknown Source) ~[na:na]
	at org.apache.dolphinscheduler.api.service.impl.ProcessDefinitionServiceImpl.releaseProcessDefinition(ProcessDefinitionServiceImpl.java:738) ~[classes/:na]
	at org.apache.dolphinscheduler.api.service.impl.ProcessDefinitionServiceImpl$$FastClassBySpringCGLIB$$e8e34ed9.invoke(<generated>) ~[classes/:na]
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) ~[spring-core-5.3.12.jar:5.3.12]
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:783) ~[spring-aop-5.3.12.jar:5.3.12]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-5.3.12.jar:5.3.12]
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753) ~[spring-aop-5.3.12.jar:5.3.12]
	at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:123) ~[spring-tx-5.3.12.jar:5.3.12]
	at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:388) ~[spring-tx-5.3.12.jar:5.3.12]
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119) ~[spring-tx-5.3.12.jar:5.3.12]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.12.jar:5.3.12]
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753) ~[spring-aop-5.3.12.jar:5.3.12]
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:698) ~[spring-aop-5.3.12.jar:5.3.12]
	at org.apache.dolphinscheduler.api.service.impl.ProcessDefinitionServiceImpl$$EnhancerBySpringCGLIB$$a6a3d50f.releaseProcessDefinition(<generated>) ~[classes/:na]
	at org.apache.dolphinscheduler.api.controller.ProcessDefinitionController.releaseProcessDefinition(ProcessDefinitionController.java:376) ~[classes/:na]
	at org.apache.dolphinscheduler.api.controller.ProcessDefinitionController$$FastClassBySpringCGLIB$$dc9bf5db.invoke(<generated>) ~[classes/:na]
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) ~[spring-core-5.3.12.jar:5.3.12]
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:783) ~[spring-aop-5.3.12.jar:5.3.12]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-5.3.12.jar:5.3.12]
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753) ~[spring-aop-5.3.12.jar:5.3.12]
	at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:89) ~[spring-aop-5.3.12.jar:5.3.12]
	at org.apache.dolphinscheduler.api.aspect.AccessLogAspect.doAround(AccessLogAspect.java:92) ~[classes/:na]
	at sun.reflect.GeneratedMethodAccessor183.invoke(Unknown Source) ~[na:na]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_291]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_291]
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:634) ~[spring-aop-5.3.12.jar:5.3.12]
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:624) ~[spring-aop-5.3.12.jar:5.3.12]
	at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:72) ~[spring-aop-5.3.12.jar:5.3.12]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175) ~[spring-aop-5.3.12.jar:5.3.12]
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753) ~[spring-aop-5.3.12.jar:5.3.12]
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97) ~[spring-aop-5.3.12.jar:5.3.12]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.3.12.jar:5.3.12]
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753) ~[spring-aop-5.3.12.jar:5.3.12]
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:698) ~[spring-aop-5.3.12.jar:5.3.12]
	at org.apache.dolphinscheduler.api.controller.ProcessDefinitionController$$EnhancerBySpringCGLIB$$50f0868f.releaseProcessDefinition(<generated>) ~[classes/:na]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_291]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_291]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_291]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_291]
	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205) ~[spring-web-5.3.12.jar:5.3.12]
	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:150) ~[spring-web-5.3.12.jar:5.3.12]
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:117) ~[spring-webmvc-5.3.12.jar:5.3.12]
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:895) ~[spring-webmvc-5.3.12.jar:5.3.12]
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:808) ~[spring-webmvc-5.3.12.jar:5.3.12]
	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) ~[spring-webmvc-5.3.12.jar:5.3.12]
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1067) ~[spring-webmvc-5.3.12.jar:5.3.12]
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:963) ~[spring-webmvc-5.3.12.jar:5.3.12]
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006) [spring-webmvc-5.3.12.jar:5.3.12]
	at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:909) [spring-webmvc-5.3.12.jar:5.3.12]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:517) [jakarta.servlet-api-4.0.4.jar:4.0.4]
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883) [spring-webmvc-5.3.12.jar:5.3.12]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:584) [jakarta.servlet-api-4.0.4.jar:4.0.4]
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1631) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
	at com.github.xiaoymin.swaggerbootstrapui.filter.SecurityBasicAuthFilter.doFilter(SecurityBasicAuthFilter.java:84) [swagger-bootstrap-ui-1.9.3.jar:na]
	at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
	at com.github.xiaoymin.swaggerbootstrapui.filter.ProductionSecurityFilter.doFilter(ProductionSecurityFilter.java:53) [swagger-bootstrap-ui-1.9.3.jar:na]
	at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.springframework.web.filter.CorsFilter.doFilterInternal(CorsFilter.java:91) [spring-web-5.3.12.jar:5.3.12]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) [spring-web-5.3.12.jar:5.3.12]
	at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) [spring-web-5.3.12.jar:5.3.12]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) [spring-web-5.3.12.jar:5.3.12]
	at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) [spring-web-5.3.12.jar:5.3.12]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) [spring-web-5.3.12.jar:5.3.12]
	at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:96) [spring-boot-actuator-2.5.6.jar:2.5.6]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) [spring-web-5.3.12.jar:5.3.12]
	at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) [spring-web-5.3.12.jar:5.3.12]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) [spring-web-5.3.12.jar:5.3.12]
	at org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:193) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1601) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:548) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:600) [jetty-security-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1434) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:501) [jetty-servlet-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1349) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:763) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.server.Server.handle(Server.java:516) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:400) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:645) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:392) [jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) ~[jetty-server-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[jetty-io-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[jetty-io-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) ~[jetty-io-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) ~[jetty-util-9.4.44.v20210927.jar:9.4.44.v20210927]
	at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_291]

2021-12-11 20:12:09.985  INFO 204909 --- [0 cport:33157):] o.a.z.server.PrepRequestProcessor        : Got user-level KeeperException when processing sessionid:0x10001d608450000 type:create cxid:0x29a zxid:0xaa txntype:-1 reqpath:n/a Error Path:/dolphinscheduler/nodes/master/10.16.80.124:5678 Error:KeeperErrorCode = NodeExists for /dolphinscheduler/nodes/master/10.16.80.124:5678
2021-12-11 20:12:10.141  INFO 204909 --- [0 cport:33157):] o.a.z.server.PrepRequestProcessor        : Got user-level KeeperException when processing sessionid:0x10001d608450000 type:create cxid:0x2a0 zxid:0xac txntype:-1 reqpath:n/a Error Path:/dolphinscheduler/nodes/worker/default/10.16.80.124:1234 Error:KeeperErrorCode = NodeExists for /dolphinscheduler/nodes/worker/default/10.16.80.124:1234
2021-12-11 20:12:19.984  INFO 204909 --- [0 cport:33157):] o.a.z.server.PrepRequestProcessor        : Got user-level KeeperException when processing sessionid:0x10001d608450000 type:create cxid:0x2aa zxid:0xae txntype:-1 reqpath:n/a Error Path:/dolphinscheduler/nodes/master/10.16.80.124:5678 Error:KeeperErrorCode = NodeExists for /dolphinscheduler/nodes/master/10.16.80.124:5678
2021-12-11 20:12:20.138  INFO 204909 --- [0 cport:33157):] o.a.z.server.PrepRequestProcessor        : Got user-level KeeperException when processing sessionid:0x10001d608450000 type:create cxid:0x2b0 zxid:0xb0 txntype:-1 reqpath:n/a Error Path:/dolphinscheduler/nodes/worker/default/10.16.80.124:1234 Error:KeeperErrorCode = NodeExists for /dolphinscheduler/nodes/worker/default/10.16.80.124:1234

2 replies

kezhenxu94 Dec 12, 2021
Collaborator

Please update the branch, this NPE is fixed.

RedemptionC Dec 12, 2021
Author

@kezhenxu94 Thank you for pointing this out!
I updated it,but there seems to be other weird things: it often jumps to the login page unnatually
these log maybe relavent:

HANDLER:org.apache.dolphinscheduler.api.controller.ProjectController.createProject, ARGS:{description=, projectName=pp}
[INFO] 2021-12-12 21:16:59.085 org.apache.zookeeper.server.PrepRequestProcessor:[653] - Got user-level KeeperException when processing sessionid:0x1000268b2d10000 type:create cxid:0x1ab zxid:0x72 txntype:-1 reqpath:n/a Error Path:/dolphinscheduler/nodes/master/10.16.80.124:5678 Error:KeeperErrorCode = NodeExists for /dolphinscheduler/nodes/master/10.16.80.124:5678
[INFO] 2021-12-12 21:16:59.208 org.apache.dolphinscheduler.api.aspect.AccessLogAspect:[81] - REQUEST TRACE_ID:9809c3da-fd9c-497f-bf74-ec4ec810f94d, LOGIN_USER:admin, URI:/dolphinscheduler/projects, METHOD:GET, HANDLER:org.apache.dolphinscheduler.api.controller.ProjectController.queryProjectListPaging, ARGS:{searchVal=, pageNo=1, pageSize=10}
[INFO] 2021-12-12 21:16:59.231 org.apache.zookeeper.server.PrepRequestProcessor:[653] - Got user-level KeeperException when processing sessionid:0x1000268b2d10000 type:create cxid:0x1b1 zxid:0x74 txntype:-1 reqpath:n/a Error Path:/dolphinscheduler/nodes/worker/default/10.16.80.124:1234 Error:KeeperErrorCode = NodeExists for /dolphinscheduler/nodes/worker/default/10.16.80.124:1234
[INFO] 2021-12-12 21:17:00.561 org.apache.dolphinscheduler.api.aspect.AccessLogAspect:[81] - REQUEST TRACE_ID:fb1a1b89-5b67-441b-a35a-8bc527b41373, LOGIN_USER:admin, URI:/dolphinscheduler/projects/analysis/process-state-count, METHOD:GET, HANDLER:org.apache.dolphinscheduler.api.controller.DataAnalysisController.countProcessInstanceState, ARGS:{endDate=2021-12-12 21:17:00, projectCode=3825231240544, startDate=2021-12-12 00:00:00}
[INFO] 2021-12-12 21:17:00.561 org.apache.dolphinscheduler.api.aspect.AccessLogAspect:[81] - REQUEST TRACE_ID:9d4256c3-a2e3-48bb-88e8-c53b5b9d7af0, LOGIN_USER:admin, URI:/dolphinscheduler/projects/analysis/task-state-count, METHOD:GET, HANDLER:org.apache.dolphinscheduler.api.controller.DataAnalysisController.countTaskState, ARGS:{endDate=2021-12-12 21:17:00, projectCode=3825231240544, startDate=2021-12-12 00:00:00}
[INFO] 2021-12-12 21:17:00.561 org.apache.dolphinscheduler.api.aspect.AccessLogAspect:[81] - REQUEST TRACE_ID:56fe7295-6c4a-4123-a076-13367c83dfcb, LOGIN_USER:admin, URI:/dolphinscheduler/projects/analysis/define-user-count, METHOD:GET, HANDLER:org.apache.dolphinscheduler.api.controller.DataAnalysisController.countDefinitionByUser, ARGS:{projectCode=3825231240544}
[INFO] 2021-12-12 21:17:02.162 org.apache.dolphinscheduler.api.aspect.AccessLogAspect:[81] - REQUEST TRACE_ID:e8916733-35e2-45fe-b0bb-dd926a7ff010, LOGIN_USER:admin, URI:/dolphinscheduler/projects/3825231240544/process-definition, METHOD:GET, HANDLER:org.apache.dolphinscheduler.api.controller.ProcessDefinitionController.queryProcessDefinitionListPaging, ARGS:{searchVal=, projectCode=3825231240544, pageNo=1, pageSize=10, userId=0}
[INFO] 2021-12-12 21:17:03.704 org.apache.dolphinscheduler.api.aspect.AccessLogAspect:[81] - REQUEST TRACE_ID:bf6ab15d-c98d-4d1d-83ea-d2f5930b93b0, LOGIN_USER:admin, URI:/dolphinscheduler/projects/created-and-authed, METHOD:GET, HANDLER:org.apache.dolphinscheduler.api.controller.ProjectController.queryProjectCreatedAndAuthorizedByUser, ARGS:{}
[INFO] 2021-12-12 21:17:03.704 org.apache.dolphinscheduler.api.aspect.AccessLogAspect:[81] - REQUEST TRACE_ID:94ad3e3d-3b00-44f8-a765-679ac6ad821c, LOGIN_USER:admin, URI:/dolphinscheduler/tenants/list, METHOD:GET, HANDLER:org.apache.dolphinscheduler.api.controller.TenantController.queryTenantlist, ARGS:{}
[INFO] 2021-12-12 21:17:03.705 org.apache.dolphinscheduler.api.aspect.AccessLogAspect:[81] - REQUEST TRACE_ID:09489287-f861-45db-8160-e7f3f1ad3d71, LOGIN_USER:admin, URI:/dolphinscheduler/worker-groups/all, METHOD:GET, HANDLER:org.apache.dolphinscheduler.api.controller.WorkerGroupController.queryAllWorkerGroups, ARGS:{}
[INFO] 2021-12-12 21:17:03.705 org.apache.dolphinscheduler.api.aspect.AccessLogAspect:[81] - REQUEST TRACE_ID:f363450c-4d7f-4c81-8bce-d472e4713f9a, LOGIN_USER:admin, URI:/dolphinscheduler/alert-groups/list, METHOD:GET, HANDLER:org.apache.dolphinscheduler.api.controller.AlertGroupController.list, ARGS:{}
[INFO] 2021-12-12 21:17:03.707 org.apache.dolphinscheduler.api.aspect.AccessLogAspect:[81] - REQUEST TRACE_ID:fdf82be8-b61e-4b58-b34b-3270e078c270, LOGIN_USER:admin, URI:/dolphinscheduler/resources/list, METHOD:GET, HANDLER:org.apache.dolphinscheduler.api.controller.ResourcesController.queryResourceList, ARGS:{type=FILE}
[WARN] 2021-12-12 21:17:04.129 org.springframework.scheduling.quartz.LocalDataSourceJobStore:[3411] - This scheduler instance (zihuatanejo1639314808977) is still active but was recovered by another instance in the cluster.  This may cause inconsistent behavior.
[INFO] 2021-12-12 21:17:05.181 org.apache.dolphinscheduler.api.security.impl.AbstractAuthenticator:[92] - session info is null 
[INFO] 2021-12-12 21:17:05.182 org.apache.dolphinscheduler.api.interceptor.LoginHandlerInterceptor:[69] - user does not exist
[INFO] 2021-12-12 21:17:09.086 org.apache.zookeeper.server.PrepRequestProcessor:[653] - Got user-level KeeperException when processing sessionid:0x1000268b2d10000 type:create cxid:0x1bd zxid:0x76 txntype:-1 reqpath:n/a Error Path:/dolphinscheduler/nodes/master/10.16.80.124:5678 Error:KeeperErrorCode = NodeExists for /dolphinscheduler/nodes/master/10.16.80.124:5678

RedemptionC · 2021-12-11T13:26:22Z

RedemptionC
Dec 11, 2021
Author

@sunnyz-l
Hi,this is the sample log ouput:
And this is the logback-standalone.xml

2021-12-11 21:14:05.097  INFO 230277 --- [andalone-Server] o.a.d.s.zk.ZookeeperCachedOperator       : register zookeeper listener: org.apache.dolphinscheduler.server.master.registry.ServerNodeManager$WorkerGroupNodeListener
2021-12-11 21:14:05.294  INFO 230277 --- [andalone-Server] d.s.w.p.DocumentationPluginsBootstrapper : Context refreshed
2021-12-11 21:14:05.306  INFO 230277 --- [andalone-Server] d.s.w.p.DocumentationPluginsBootstrapper : Found 1 custom documentation plugin(s)
2021-12-11 21:14:05.326  INFO 230277 --- [andalone-Server] s.d.s.w.s.ApiListingReferenceScanner     : Scanning for api listing references
2021-12-11 21:14:05.496  INFO 230277 --- [andalone-Server] .d.s.w.r.o.CachingOperationNameGenerator : Generating unique operation named: viewTreeUsingGET_1
2021-12-11 21:14:05.588  INFO 230277 --- [andalone-Server] o.e.j.s.h.ContextHandler.application     : Initializing Spring DispatcherServlet 'dispatcherServlet'
2021-12-11 21:14:05.598  INFO 230277 --- [andalone-Server] org.mortbay.log                          : Logging to Logger[org.mortbay.log] via org.mortbay.log.Slf4jLog
2021-12-11 21:14:05.876  INFO 230277 --- [andalone-Server] o.e.jetty.server.AbstractConnector       : Started ServerConnector@1bedc703{HTTP/1.1, (http/1.1)}{0.0.0.0:12345}
2021-12-11 21:14:05.882  INFO 230277 --- [andalone-Server] o.a.d.remote.NettyRemotingServer         : NettyRemotingServer bind success at port : 50051
2021-12-11 21:14:05.882  INFO 230277 --- [andalone-Server] o.a.d.server.log.LoggerServer            : logger server started, listening on port : 50051
2021-12-11 21:14:05.884  INFO 230277 --- [andalone-Server] o.a.d.common.plugin.FilePluginManager    : start to load jar files in /Users/xx/your/path/to/plugin/dir
2021-12-11 21:14:05.884 ERROR 230277 --- [andalone-Server] o.a.d.common.plugin.FilePluginManager    : not a valid path - /Users/xx/your/path/to/plugin/dir
2021-12-11 21:14:05.885  INFO 230277 --- [andalone-Server] o.a.dolphinscheduler.alert.AlertServer   : alert server ready start 
2021-12-11 21:15:37.141  INFO 230277 --- [p1279124366-171] o.a.d.a.security.PasswordAuthenticator   : session info is null 
2021-12-11 21:15:37.141  INFO 230277 --- [p1279124366-171] o.a.d.a.i.LoginHandlerInterceptor        : user does not exist
2021-12-11 21:15:38.809  INFO 230277 --- [tp1279124366-66] o.a.d.api.controller.LoginController     : login user name: admin 
2021-12-11 21:15:38.823  INFO 230277 --- [tp1279124366-66] o.a.d.a.security.PasswordAuthenticator   : sessionId : 17758c4b-b432-4770-9642-ee701389b517
2021-12-11 21:15:40.217  INFO 230277 --- [tp1279124366-67] o.a.d.api.controller.UsersController     : login user admin,get user info
2021-12-11 21:15:40.494  INFO 230277 --- [tp1279124366-68] o.a.d.api.controller.TenantController    : login user admin, list paging, pageNo: 1, searchVal: , pageSize: 10
2021-12-11 21:15:43.257  INFO 230277 --- [tp1279124366-69] o.a.d.api.controller.UsersController     : login user admin, list user paging, pageNo: 1, searchVal: , pageSize: 10
2021-12-11 21:15:44.667  INFO 230277 --- [tp1279124366-70] o.a.d.api.controller.TenantController    : login user admin, list paging, pageNo: 1, searchVal: , pageSize: 10
2021-12-11 21:15:45.551  INFO 230277 --- [tp1279124366-71] o.a.d.api.controller.QueueController     : login user admin, query queue list
2021-12-11 21:15:49.160  INFO 230277 --- [tp1279124366-64] o.a.d.api.controller.TenantController    : login user admin, verfiy tenant code: ttt
2021-12-11 21:15:49.169  INFO 230277 --- [p1279124366-169] o.a.d.api.controller.TenantController    : login user admin, create tenant, tenantCode: ttt, tenantName: ttt, queueId: 1, desc: 
2021-12-11 21:15:49.282  INFO 230277 --- [tp1279124366-65] o.a.d.api.controller.TenantController    : login user admin, list paging, pageNo: 1, searchVal: , pageSize: 10
2021-12-11 21:15:50.388  INFO 230277 --- [p1279124366-172] o.a.d.api.controller.UsersController     : login user admin, list user paging, pageNo: 1, searchVal: , pageSize: 10

1 reply

Lucaszlei Dec 13, 2021

It can be seen from the printed log that the logback-standalone.xml log configuration is not used, please add -Dlogging.config=classpath:logback-standalone.xml JVM parameter when starting standalone

RedemptionC · 2021-12-13T10:25:29Z

RedemptionC
Dec 13, 2021
Author

It can be seen from the printed log that the logback-standalone.xml log configuration is not used, please add -Dlogging.config=classpath:logback-standalone.xml JVM parameter when starting standalone

Yes , this is the answer

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fail to execute simple shell task in 1.39 release standalone mode #7323

{{title}}

Replies: 5 comments 4 replies

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

Select a reply

fail to execute simple shell task in 1.39 release standalone mode #7323

RedemptionC Dec 10, 2021

Replies: 5 comments · 4 replies

Lucaszlei Dec 10, 2021

RedemptionC Dec 10, 2021 Author

RedemptionC Dec 11, 2021 Author

RedemptionC Dec 11, 2021 Author

kezhenxu94 Dec 12, 2021 Collaborator

RedemptionC Dec 12, 2021 Author

RedemptionC Dec 11, 2021 Author

Lucaszlei Dec 13, 2021

RedemptionC Dec 13, 2021 Author

RedemptionC
Dec 10, 2021

Replies: 5 comments 4 replies

Lucaszlei
Dec 10, 2021

RedemptionC Dec 10, 2021
Author

RedemptionC
Dec 11, 2021
Author

RedemptionC
Dec 11, 2021
Author

kezhenxu94 Dec 12, 2021
Collaborator

RedemptionC Dec 12, 2021
Author

RedemptionC
Dec 11, 2021
Author

RedemptionC
Dec 13, 2021
Author