MP system.log logging in tmp files

[jaganathdora]

Recently we build 4 new Message processor servers. The system .log file gets backed up every night. The issue we are seeing with MP logs is that Message processor logs are getting written into .tmp file after backup.

system.log1377973859882525.tmp

If we stop the services and then restart it writes the file correctly as system.log.

This is not the issue with router logs, they also gets rotated everynight.

I checked /opt/apigee/edge-message-processor/conf/logback.xml and permission on the folders and everything looks same as working servers.

Does anyone knows what could be causing the issue ? What else we can check to fix the issue.

[API-Evangelist]

What did mp logs say? Can you paste error information? is it related to file descriptors?

https://community.apigee.com/articles/1422/apigee-edge-opdk-file-descriptors-recommendations.html

[jaganathdora]

Hi Vinay thanks for the reply, the logs are showing clean. I do not see any error. The issues seems to be what Priyadarshi mentioned below.

for some reason its not able to zip the files.

[jaganathdora]

Vinay here is the error in logs.

2021-03-27 10:35:42,119 NIOThread@6 ERROR HTTP.SERVER - HTTPServer.onAcceptFailure() : accept from ServerChannel[xxx:8998]@1 failed
java.io.IOException: Too many open files
at sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method) ~[na:1.8.0_162]
at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:422) ~[na:1.8.0_162]
at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:250) ~[na:1.8.0_162]
at com.apigee.nio.ServerChannel.accept(ServerChannel.java:54) ~[nio-1.0.0.jar:na]
at com.apigee.nio.handlers.NIOThread.run(NIOThread.java:103) ~[nio-1.0.0.jar:na]
2021-03-27 10:35:44,908 globalEventExecutor-1-2 WARN i.n.u.c.DefaultPromise - Slf4JLogger.warn() : An exception was thrown by com.apigee.rpc.impl.ClientHandleImpl$2.operationComplete()
java.lang.NullPointerException: null
at com.apigee.rpc.impl.ClientHandleImpl.sendHandshake(ClientHandleImpl.java:131) ~[rpc-1.0.0.jar:na]
at com.apigee.rpc.impl.ClientHandleImpl$2.operationComplete(ClientHandleImpl.java:121) ~[rpc-1.0.0.jar:na]
at com.apigee.rpc.impl.ClientHandleImpl$2.operationComplete(ClientHandleImpl.java:118) ~[rpc-1.0.0.jar:na]
at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:507) [netty-all-4.1.13.Final.jar:4.1.13.Final]
at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:481) [netty-all-4.1.13.Final.jar:4.1.13.Final]
at io.netty.util.concurrent.DefaultPromise.access$000(DefaultPromise.java:34) [netty-all-4.1.13.Final.jar:4.1.13.Final]
at io.netty.util.concurrent.DefaultPromise$1.run(DefaultPromise.java:431) [netty-all-4.1.13.Final.jar:4.1.13.Final]
at io.netty.util.concurrent.GlobalEventExecutor$TaskRunner.run(GlobalEventExecutor.java:233) [netty-all-4.1.13.Final.jar:4.1.13.Final]
at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:138) [netty-all-4.1.13.Final.jar:4.1.13.Final]
at java.lang.Thread.run(Thread.java:748) [na:1.8.0_162]
2021-03-27 10:35:44,908 globalEventExecutor-1-2 WARN i.n.u.c.DefaultPromise - Slf4JLogger.warn() : An exception was thrown by com.apigee.rpc.impl.ClientHandleImpl$2.operationComplete()
java.lang.NullPointerException: null
at com.apigee.rpc.impl.ClientHandleImpl.sendHandshake(ClientHandleImpl.java:131) ~[rpc-1.0.0.jar:na]
at com.apigee.rpc.impl.ClientHandleImpl$2.operationComplete(ClientHandleImpl.java:121) ~[rpc-1.0.0.jar:na]
at com.apigee.rpc.impl.ClientHandleImpl$2.operationComplete(ClientHandleImpl.java:118) ~[rpc-1.0.0.jar:na]
at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:507) [netty-all-4.1.13.Final.jar:4.1.13.Final]
at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:481) [netty-all-4.1.13.Final.jar:4.1.13.Final]
at io.netty.util.concurrent.DefaultPromise.access$000(DefaultPromise.java:34) [netty-all-4.1.13.Final.jar:4.1.13.Final]
at io.netty.util.concurrent.DefaultPromise$1.run(DefaultPromise.java:431) [netty-all-4.1.13.Final.jar:4.1.13.Final]
at io.netty.util.concurrent.GlobalEventExecutor$TaskRunner.run(GlobalEventExecutor.java:233) [netty-all-4.1.13.Final.jar:4.1.13.Final]
at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:138) [netty-all-4.1.13.Final.jar:4.1.13.Final]
at java.lang.Thread.run(Thread.java:748) [na:1.8.0_162]
2021-03-27 10:36:23,768 NIOThread@3 ERROR HTTP.SERVER - HTTPServer.onAcceptFailure() : accept from ServerChannel[xxx:8998]@1 failed
java.io.IOException: Too many open files

[API-Evangelist]

Not sure but error looks to be file descriptor issues.

==

java.io.IOException: Too many open files

==

If it is resolved then it is fine else speak to linux admin and have ulimits adjusted.

[#6]

This will get resolved if you restart the rmp. This is because at a time too many connections are writing to file.

[jaganathdora]

@

Priyadarshi Ajitav Jena yes we have been doing that for now but we are looking for a log term solution. I have a case opened with apigee will let you know if i hear back anything from them. so far they told me pretty much the same things which you and Vinay told me :(.

[jaganathdora]

@vinay, yes thats one of the option but this raised to a question why only these new MP are having issue. I have the same set if MP which are in use and do not have this issue. based on lsof output i see it does lot of FIFO and PIPES.

[#9]

It seems the backup Process is not completing successfully.

The backup script creates a temp first and later if deletes the temp at the end. In your case it's not deleting the temp and not creating the gz zip file.

Just check the permission of your backup directory and see the apigee user is having root privilege or similar.

[jaganathdora]

Priyadarshi, thanks for your reply.

I chekced the permission on the folders and compared it with existing servers where its able to rotate the logs. They have same permisson.

$ ls -ld /opt/apigee/edge-message-processor-4.18.01

drwxrwxr-x xxxxx xxxxx /opt/apigee/edge-message-processor-4.18.01

$ ls -ld /opt/apigee/var/log/edge\-message\-processor/logs

drwxr-x--- xxxxx xxxxx /opt/apigee/var/log/edge-message-processor/logs

[#11]

/opt/apigee all directories owned by apigee?

[jaganathdora]

We do notuse apigee user id to run the setup, we have our own user id and yes all are owned by same user id and group.

[#13]

Is this the same in other working one?

[jaganathdora]

yes, its same as mentioned above. We have the same permission / access on the folders.