search

opensearch-project / OpenSearch

🔎 Open source distributed and RESTful search engine.
https://opensearch.org/docs/latest/opensearch/index/
Apache License 2.0
9.74k stars 1.81k forks source link

[BUG] Access denied error opening rotated log files #9609

Open AlexRuiz7 opened 1 year ago

AlexRuiz7 commented 1 year ago

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):

[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

```java 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 commented 9 months ago

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

AlexRuiz7 commented 9 months ago

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 commented 9 months ago

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.

AlexRuiz7 commented 9 months ago

Thanks for the reply!

I installed OpenSearch on a Vagrant box and that's it.

I think I removed the environment sometime ago, so I'll try to reproduce it and get back with more details.

Mudboyzh commented 8 months ago

I got the same issue. There is a solution from the forum. It works for me.

AlexRuiz7 commented 6 months ago

It's working. Thanks @Mudboyzh

sebix commented 3 months ago

I installed OpenSearch on a Vagrant box and that's it.

I see the same issue with the deb packages on Debian bookworm with OpenSearch version 2.15.0.