marekt
Intern
Intern
  • UID5816
  • Fans0
  • Follows0
  • Posts11
Reads:84923Replies:8

log4j error in java8 in cold start

Created#
More Posted time:Nov 23, 2018 8:58 AM
Hi,


I'm experiencing problems with in cold start and initialization of logger. Here is my problem and how to reproduce it:


1. Create java8 function
2. Upload jar file from attached repo or build from the source code
3. Invoke function and on first invoke there is following log:

eflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.logging.log4j.core.config.plugins.util.PluginBuilder.build(PluginBuilder.java:133)
at org.apache.logging.log4j.core.config.AbstractConfiguration.createPluginObject(AbstractConfiguration.java:744)
at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:683)
at org.apache.logging.log4j.core.config.AbstractConfiguration.createConfiguration(AbstractConfiguration.java:675)
at org.apache.logging.log4j.core.config.AbstractConfiguration.doConfigure(AbstractConfiguration.java:349)
at org.apache.logging.log4j.core.config.AbstractConfiguration.start(AbstractConfiguration.java:150)
at org.apache.logging.log4j.core.LoggerContext.setConfiguration(LoggerContext.java:364)
at org.apache.logging.log4j.core.LoggerContext.reconfigure(LoggerContext.java:422)
at org.apache.logging.log4j.core.LoggerContext.start(LoggerContext.java:146)
at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:85)
at org.apache.logging.log4j.core.impl.Log4jContextFactory.getContext(Log4jContextFactory.java:37)
at org.apache.logging.log4j.LogManager.getContext(LogManager.java:269)
at org.apache.logging.slf4j.Log4jLoggerFactory$PrivateManager.getContext(Log4jLoggerFactory.java:98)
at org.apache.logging.slf4j.Log4jLoggerFactory.getContext(Log4jLoggerFactory.java:84)
at org.apache.logging.slf4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:44)
at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:277)
at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:288)
at com.alicloud.openservices.tablestore.core.TraceLogger.<clinit>(TraceLogger.java:14)
at com.alicloud.openservices.tablestore.InternalClient.getTraceLogger(InternalClient.java:171)
at com.alicloud.openservices.tablestore.InternalClient.getRow(InternalClient.java:318)
at com.alicloud.openservices.tablestore.SyncClient.getRow(SyncClient.java:146)
at earth.soar.api.handlers.RequestHandler.handleRequest(RequestHandler.java:24)
at aliyun.serverless.runtime.CARequestHandler.callUserFunction(CARequestHandler.java:155)
at aliyun.serverless.runtime.CARequestHandler.handleUserRequest(CARequestHandler.java:238)
at aliyun.serverless.runtime.CARequestHandler.handle(CARequestHandler.java:259)
at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:79)
at sun.net.httpserver.AuthFilter.doFilter(AuthFilter.java:83)
at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:82)
at sun.net.httpserver.ServerImpl$Exchange$LinkHandler.handle(ServerImpl.java:675)
at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:79)
at sun.net.httpserver.ServerImpl$Exchange.run(ServerImpl.java:647)
at sun.net.httpserver.ServerImpl$DefaultExecutor.execute(ServerImpl.java:158)
at sun.net.httpserver.ServerImpl$Dispatcher.handle(ServerImpl.java:431)
at sun.net.httpserver.ServerImpl$Dispatcher.run(ServerImpl.java:396)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.IllegalStateException: Unable to create a manager
at org.apache.logging.log4j.core.appender.AbstractManager.getManager(AbstractManager.java:73)
at org.apache.logging.log4j.core.appender.OutputStreamManager.getManager(OutputStreamManager.java:60)
at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.getFileManager(RollingFileManager.java:79)
at org.apache.logging.log4j.core.appender.RollingFileAppender.createAppender(RollingFileAppender.java:182)
... 39 more
2018-11-23 00:37:01,292 ERROR Unable to invoke factory method in class class org.apache.logging.log4j.core.appender.RollingFileAppender for element RollingFile.
2018-11-23 00:37:01,293 ERROR Null object returned for RollingFile in Appenders.
2018-11-23 00:37:01,296 ERROR Unable to locate appender fc-runtime-log for logger
FC Invoke End RequestId: c9aa9539-a24a-89cc-6fd6-6f0e3a471299

4. The following invokes are fine without any error
5. Request finishes and returns correct data but problem is when connect this function with api gateway then the API Gateway return 503 error. Then I call the same request again and returns expected results without any problem.


You can find repository with the example project at this link:


https://github.com/mtlacbaba/fc-function-log4j-error



So as I mentioned before it is happening only on cold start so easy way to reproduce it is to upload the code and invoke function.


Regards,
Marek T

Raja_KT
Architect
Architect
  • UID6384
  • Fans4
  • Follows3
  • Posts555
1st Reply#
Posted time:Nov 23, 2018 21:33 PM
I am not sure much about the background. But  I am thunking , we are using the "Log Service" . In that way we can centralize the logging system :). Please correct me.

https://www.alibabacloud.com/help/product/28958.htm?spm=a2c63.p38356.a1.2.41143610JDXbr3
Street children suffer not because of their fault. We can help them if we want.Contact me.

marekt
Intern
Intern
  • UID5816
  • Fans0
  • Follows0
  • Posts11
2nd Reply#
Posted time:Nov 24, 2018 11:08 AM
Hi, that is correct but the problem is that the function throws this error, error is logged and shown in log service and then function finishes and return value and this happens only on cold start. But this error is picked up by API Gateway integration and gateway returns 503 error back to client. The following request is without error and API Gateway integration returns correct result.

RyanZhang
Intern
Intern
  • UID6135
  • Fans0
  • Follows0
  • Posts7
3rd Reply#
Posted time:Nov 27, 2018 12:13 PM
Hi,  I wonder if you can use the logger that the function compute provide instead of the log4j?

marekt
Intern
Intern
  • UID5816
  • Fans0
  • Follows0
  • Posts11
4Floor#
Posted time:Nov 27, 2018 12:17 PM
The error actually in this case comes from TableStore library and there are the other libraries we are using in the project that needs log4j too.

RyanZhang
Intern
Intern
  • UID6135
  • Fans0
  • Follows0
  • Posts7
5Floor#
Posted time:Nov 27, 2018 12:17 PM
@marekt,  as for the api-gateway 503 issue, I wonder if you can tell me how long was the timeout set for the api-gateway? It's most likely that the gateway timed out

marekt
Intern
Intern
  • UID5816
  • Fans0
  • Follows0
  • Posts11
6Floor#
Posted time:Nov 27, 2018 12:27 PM
I believe I've configured API Gateway integration correctly. The 503 is returns only when the FcFunction wakes up (cold start) after new deployement or if not used for a while. When I call the request again then everything works as intended. Also we use FUN (https://github.com/aliyun/fun) to configure and deploy API Gateway and FcFunction together so there should not be a problem in configuration. And as I said it happens only on cold start. The second run everything works correctly.

marekt
Intern
Intern
  • UID5816
  • Fans0
  • Follows0
  • Posts11
7Floor#
Posted time:Nov 27, 2018 12:34 PM
Thanks for this advice. I was setting just timeout on function itself. The timeout on API Gateway was only default 3000ms which wasn't enough for cold start. Increasing the time there solved the problem. But the error from log4j is confusing anyway.

Raja_KT
Architect
Architect
  • UID6384
  • Fans4
  • Follows3
  • Posts555
8Floor#
Posted time:Nov 28, 2018 14:35 PM
Thanks Marek for sharing. Maybe if you can share the increased value ( threshold) so that we can take care next time :)
Street children suffer not because of their fault. We can help them if we want.Contact me.
Guest