[BUG] Access denied error opening rotated log files

[AlexRuiz7]

Describe the bug

This error shows up when the rotation of logs is performed:

main ERROR Could not define attribute view on path "/var/log/opensearch/opensearch.log" got access denied ("java.lang.RuntimePermission" "accessUserInformation") java.security.AccessControlException: access denied ("java.lang.RuntimePermission" "accessUserInformation")

We've been able to replicate this problem is several operative systems and OpenSearch versions (present in latest version 2.9.0)

To Reproduce
Steps to reproduce the behavior:

1. Install OpenSearch 2.9.0
2. Wait (or force) for the rotation of logs
3. Check the logs with journalctl
4. See error

Expected behavior
No errors

Plugins
All plugins enabled by default.

Screenshots
If applicable, add screenshots to help explain your problem.

Host/Environment (please complete the following information):

• OS: [RHEL 7, CentOS 7, Ubuntu22.04]

[root@redhat-7 ~]# yum info opensearch
Loaded plugins: product-id, search-disabled-repos
Installed Packages
Name        : opensearch
Arch        : x86_64
Version     : 2.9.0
Release     : 1
Size        : 993 M
Repo        : installed
From repo   : /opensearch-2.9.0-linux-x64
Summary     : An open source distributed and RESTful search engine
URL         : https://opensearch.org/
License     : Apache-2.0
Description : OpenSearch makes it easy to ingest, search, visualize, and analyze your data
            : For more information, see: https://opensearch.org/

Additional context
Extended logs

Details

Aug 28 12:00:46 ubuntu2204.localdomain systemd[1]: Started OpenSearch.
░░ Subject: A start job for unit opensearch.service has finished successfully
░░ Defined-By: systemd
░░ Support: http://www.ubuntu.com/support
░░ 
░░ A start job for unit opensearch.service has finished successfully.
░░ 
░░ The job identifier is 120.
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]: 2023-08-29 14:22:59,217 opensearch[ubuntu2204.localdomain][scheduler][T#1] ERROR Could not define attribute view on path "/var/log/opensearch/opensearch_server.json" got access denied ("java.lang.RuntimePermission" "accessUserInformation") java.security.AccessControlException: access denied ("java.lang.RuntimePermission" "accessUserInformation")
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at java.base/java.security.AccessControlContext.checkPermission(AccessControlContext.java:485)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at java.base/java.security.AccessController.checkPermission(AccessController.java:1068)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at java.base/java.lang.SecurityManager.checkPermission(SecurityManager.java:416)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at java.base/sun.nio.fs.UnixFileAttributeViews$Posix.checkWriteExtended(UnixFileAttributeViews.java:195)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at java.base/sun.nio.fs.UnixFileAttributeViews$Posix.setMode(UnixFileAttributeViews.java:264)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at java.base/sun.nio.fs.UnixFileAttributeViews$Posix.setPermissions(UnixFileAttributeViews.java:299)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.util.FileUtils.defineFilePosixAttributeView(FileUtils.java:177)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.appender.FileManager.defineAttributeView(FileManager.java:215)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.appender.FileManager.createOutputStream(FileManager.java:202)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.createFileAfterRollover(RollingFileManager.java:419)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.rollover(RollingFileManager.java:396)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.checkRollover(RollingFileManager.java:308)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.appender.RollingFileAppender.append(RollingFileAppender.java:311)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:161)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:134)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:125)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:89)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:542)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:500)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:483)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:417)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:82)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.Logger.log(Logger.java:161)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2205)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2159)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2142)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2017)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1983)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.spi.AbstractLogger.info(AbstractLogger.java:1320)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.opensearch.jobscheduler.sweeper.JobSweeper.lambda$initBackgroundSweep$10(JobSweeper.java:294)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.opensearch.threadpool.Scheduler$ReschedulingRunnable.doRun(Scheduler.java:239)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.opensearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:806)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.opensearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:52)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at java.base/java.lang.Thread.run(Thread.java:833)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]: 2023-08-29 14:22:59,222 opensearch[ubuntu2204.localdomain][scheduler][T#1] ERROR Could not define attribute view on path "/var/log/opensearch/opensearch.log" got access denied ("java.lang.RuntimePermission" "accessUserInformation") java.security.AccessControlException: access denied ("java.lang.RuntimePermission" "accessUserInformation")
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at java.base/java.security.AccessControlContext.checkPermission(AccessControlContext.java:485)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at java.base/java.security.AccessController.checkPermission(AccessController.java:1068)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at java.base/java.lang.SecurityManager.checkPermission(SecurityManager.java:416)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at java.base/sun.nio.fs.UnixFileAttributeViews$Posix.checkWriteExtended(UnixFileAttributeViews.java:195)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at java.base/sun.nio.fs.UnixFileAttributeViews$Posix.setMode(UnixFileAttributeViews.java:264)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at java.base/sun.nio.fs.UnixFileAttributeViews$Posix.setPermissions(UnixFileAttributeViews.java:299)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.util.FileUtils.defineFilePosixAttributeView(FileUtils.java:177)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.appender.FileManager.defineAttributeView(FileManager.java:215)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.appender.FileManager.createOutputStream(FileManager.java:202)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.createFileAfterRollover(RollingFileManager.java:419)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.rollover(RollingFileManager.java:396)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.appender.rolling.RollingFileManager.checkRollover(RollingFileManager.java:308)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.appender.RollingFileAppender.append(RollingFileAppender.java:311)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:161)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:134)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:125)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:89)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:542)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:500)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:483)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:417)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:82)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.core.Logger.log(Logger.java:161)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2205)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2159)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2142)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2017)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1983)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.apache.logging.log4j.spi.AbstractLogger.info(AbstractLogger.java:1320)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.opensearch.jobscheduler.sweeper.JobSweeper.lambda$initBackgroundSweep$10(JobSweeper.java:294)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.opensearch.threadpool.Scheduler$ReschedulingRunnable.doRun(Scheduler.java:239)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.opensearch.common.util.concurrent.ThreadContext$ContextPreservingAbstractRunnable.doRun(ThreadContext.java:806)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at org.opensearch.common.util.concurrent.AbstractRunnable.run(AbstractRunnable.java:52)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
Aug 29 14:22:59 ubuntu2204.localdomain systemd-entrypoint[661]:         at java.base/java.lang.Thread.run(Thread.java:833)

File permissions before the rotation:

[root@redhat-7 ~]# ls -la /var/log/opensearch/
total 524
drwxr-sr-x.  2 opensearch opensearch   4096 Aug 28 13:37 .
drwxr-xr-x. 11 root       root         4096 Aug 28 13:44 ..
-rw-r--r--.  1 opensearch opensearch 143656 Aug 28 13:49 gc.log
-rw-r--r--.  1 opensearch opensearch   2006 Aug 28 13:37 gc.log.00
-rw-r--r--.  1 opensearch opensearch   1693 Aug 28 13:37 install_demo_configuration.log
-rw-r-----.  1 opensearch opensearch    834 Aug 28 13:37 opensearch_deprecation.json
-rw-r-----.  1 opensearch opensearch    513 Aug 28 13:37 opensearch_deprecation.log
-rw-r-----.  1 opensearch opensearch      0 Aug 28 13:37 opensearch_index_indexing_slowlog.json
-rw-r-----.  1 opensearch opensearch      0 Aug 28 13:37 opensearch_index_indexing_slowlog.log
-rw-r-----.  1 opensearch opensearch      0 Aug 28 13:37 opensearch_index_search_slowlog.json
-rw-r-----.  1 opensearch opensearch      0 Aug 28 13:37 opensearch_index_search_slowlog.log
-rw-r-----.  1 opensearch opensearch  50722 Aug 28 13:47 opensearch.log
-rw-r-----.  1 opensearch opensearch 104571 Aug 28 13:47 opensearch_server.json
-rw-r-----.  1 opensearch opensearch      0 Aug 28 13:37 opensearch_task_detailslog.json
-rw-r-----.  1 opensearch opensearch      0 Aug 28 13:37 opensearch_task_detailslog.log

File permissions after the rotation:

[vagrant@redhat-7 ~]$ sudo su -
Last login: Mon Aug 28 13:34:03 UTC 2023 on pts/0
[root@redhat-7 ~]# journalctl | grep -i opensearch.log
Aug 29 13:50:36 redhat-7 systemd-entrypoint[688]: 2023-08-29 13:50:36,540 main ERROR Could not define attribute view on path "/var/log/opensearch/opensearch.log" got access denied ("java.lang.RuntimePermission" "accessUserInformation") java.security.AccessControlException: access denied ("java.lang.RuntimePermission" "accessUserInformation")
[root@redhat-7 ~]# ls -la /var/log/opensearch/
total 412
drwxr-sr-x.  2 opensearch opensearch   4096 Aug 29 13:50 .
drwxr-xr-x. 11 root       root         4096 Aug 29 13:50 ..
-rw-r--r--.  1 opensearch opensearch  39712 Aug 29 13:51 gc.log
-rw-r--r--.  1 opensearch opensearch   2006 Aug 28 13:37 gc.log.00
-rw-r--r--.  1 opensearch opensearch 146505 Aug 28 13:50 gc.log.01
-rw-r--r--.  1 opensearch opensearch   2006 Aug 29 13:50 gc.log.02
-rw-r--r--.  1 opensearch opensearch   1693 Aug 28 13:37 install_demo_configuration.log
-rw-r--r--.  1 opensearch opensearch   9178 Aug 29 13:50 opensearch-2023-08-28-1.json.gz
-rw-r--r--.  1 opensearch opensearch   8390 Aug 29 13:50 opensearch-2023-08-28-1.log.gz
-rw-r-----.  1 opensearch opensearch   1204 Aug 29 13:50 opensearch_deprecation.json
-rw-r-----.  1 opensearch opensearch    766 Aug 29 13:50 opensearch_deprecation.log
-rw-r-----.  1 opensearch opensearch      0 Aug 28 13:37 opensearch_index_indexing_slowlog.json
-rw-r-----.  1 opensearch opensearch      0 Aug 28 13:37 opensearch_index_indexing_slowlog.log
-rw-r-----.  1 opensearch opensearch      0 Aug 28 13:37 opensearch_index_search_slowlog.json
-rw-r-----.  1 opensearch opensearch      0 Aug 28 13:37 opensearch_index_search_slowlog.log
-rw-r--r--.  1 opensearch opensearch  46201 Aug 29 13:50 opensearch.log
-rw-r--r--.  1 opensearch opensearch  84227 Aug 29 13:50 opensearch_server.json
-rw-r-----.  1 opensearch opensearch      0 Aug 28 13:37 opensearch_task_detailslog.json
-rw-r-----.  1 opensearch opensearch      0 Aug 28 13:37 opensearch_task_detailslog.log

[peterzhuamazon]

What user are you using for the log rotation @AlexRuiz7 ? Does the user in the group of opensearch?

[AlexRuiz7]

Hello @peterzhuamazon

Thanks for the reply.

opensearch:opensearch I assume. I haven't really specified any user or group, so I assume the user and group created by OpenSearch are in use.

[peterzhuamazon]

I am not able to reproduce this on my side tho.

@AlexRuiz7 could you detailed your steps and commands you used? As well as the permission and ownership of /var/log/opensearch (this particular folder)

Thanks.