SELinux有効でlogrotateによるログのローテートに失敗した話
2023-06-13 - 相本 智仁
SELinux が有効な環境で OpenAM のログに対してのログのローテートが行われていませんでした。/var/log/messageに以下のエラーが出力されていました。
- /var/log/message
Jun 13 00:00:05 alma9sp2 systemd[1]: Starting Rotate log files...
Jun 13 00:00:05 alma9sp2 logrotate[45638]: error: cannot allocate memory [readConfigFile():1806]
Jun 13 00:00:05 alma9sp2 logrotate[45638]: error: found error in file openam, skipping
cannot allocate memoryはメモリを確保できない旨を示すメッセージです。
しかし、サーバーのメモリは不足しておらず他のログのローテートは成功していました。
(もしメモリ不足であれば、他の処理でも失敗するはずです。)
logrotate が失敗したのは SELinux が原因だったのですが、どうしてcannot allocate memoryのメッセージが出力されたのかを調べました。
logrotate が失敗した環境
OS は AlmaLinux9 で SELinux が有効な環境です。 logrotateの設定ファイルでログローテートの対象として指定している先はシンボリックリンクです。
- SELinuxが有効
# getenforce
Enforcing
- logrotateのバージョン
# rpm -qa logrotate
logrotate-3.18.0-8.el9.x86_64
- エラーとなったlogrotateの設定ファイル(openam)
/opt/osstech/var/lib/tomcat/data/openam/openam/stats/*
/opt/osstech/var/lib/tomcat/data/openam/openam/debug/*
{
rotate 100
daily
su tomcat tomcat
notifempty
missingok
copytruncate
olddir old
dateext
compress
nodelaycompress
sharedscripts
postrotate
[OpenDJや監査ログをローテートするシェルスクリプトのコード]
endscript
}
- ローテート対象のディレクトリ
# ls -l /opt/osstech/var/lib/tomcat/data/openam/openam/stats
lrwxrwxrwx. 1 root root 21 Jun 12 13:48 /opt/osstech/var/lib/tomcat/data/openam/openam/stats -> /logdata/openam/stats
# ls -l /opt/osstech/var/lib/tomcat/data/openam/openam/debug
lrwxrwxrwx. 1 root root 21 Jun 12 13:48 /opt/osstech/var/lib/tomcat/data/openam/openam/debug -> /logdata/openam/debug
# ls -l /opt/osstech/var/lib/tomcat/data/openam/openam/stats/
total 76
-rw-r-----. 1 tomcat tomcat 899 Jun 12 13:38 Entitlements
-rw-r-----. 1 tomcat tomcat 18064 Jun 12 15:20 amMasterSessionTableStats
-rw-r-----. 1 tomcat tomcat 51150 Jun 12 15:20 idRepoCacheStat
drwxr-x---. 2 tomcat tomcat 6 Jun 12 13:36 old
# ls -l /opt/osstech/var/lib/tomcat/data/openam/openam/debug/
total 24
-rw-r-----. 1 tomcat tomcat 4941 Jun 12 13:40 CoreSystem
-rw-r-----. 1 tomcat tomcat 181 Jun 12 13:39 IdRepo
-rw-r-----. 1 tomcat tomcat 9808 Jun 12 13:39 Session
drwxr-x---. 2 tomcat tomcat 6 Jun 12 13:39 old
logrotate が失敗した原因
auditログに記録がありSELinuxが原因でした。 ausearch で auditログを検索した結果が次のとおりです。
time->Tue Jun 13 00:00:05 2023
type=PROCTITLE msg=audit(1686582005.310:2981): proctitle=2F7573722F7362696E2F6C6F67726F74617465002F6574632F6C6F67726F746174652E636F6E66
type=SYSCALL msg=audit(1686582005.310:2981): arch=c000003e syscall=257 success=no exit=-13 a0=ffffff9c a1=7ffccfc4ae80 a2=90800 a3=0 items=0 ppid=1 pid=45638 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="logrotate" exe="/usr/sbin/logrotate" subj=system_u:system_r:logrotate_t:s0 key=(null)
type=AVC msg=audit(1686582005.310:2981): avc: denied { read } for pid=45638 comm="logrotate" name="stats" dev="vda2" ino=204957 scontext=system_u:system_r:logrotate_t:s0 tcontext=unconfined_u:object_r:var_lib_t:s0 tclass=lnk_file permissive=0
このログからlogrotateのセキュリティコンテキストsystem_u:system_r:logrotate_t:s0が、unconfined_u:object_r:var_lib_t:s0のlnk_file(シンボリックリンク)に対して read を拒否したことがわかります。
シンボリックリンクのセキュリティコンテキストのタイプは var_lib_t でした。
# ls -ldZ /opt/osstech/var/lib/tomcat/data/openam/openam/{stats,debug}
lrwxrwxrwx. 1 root root unconfined_u:object_r:var_lib_t:s0 21 Jun 12 16:02 /opt/osstech/var/lib/tomcat/data/openam/openam/debug -> /logdata/openam/debug
lrwxrwxrwx. 1 root root unconfined_u:object_r:var_lib_t:s0 21 Jun 12 16:02 /opt/osstech/var/lib/tomcat/data/openam/openam/stats -> /logdata/openam/stats
runconコマンドで logrotate を実行したところ(テストのためオプションに-dも付けました)、簡単に事象を再現させることが出来ました。
# runcon system_u:system_r:logrotate_t:s0 /usr/sbin/logrotate -d /opt/osstech/etc/logrotate.d/openam
WARNING: logrotate in debug mode does nothing except printing debug messages! Consider using verbose mode (-v) instead if this is not what you want.
reading config file /opt/osstech/etc/logrotate.d/openam
error: cannot allocate memory [readConfigFile():1806]
olddir is now old
〜
SELinux の Access Vector Rules の許可ルールを確認し、シンボリックリンクのセキュリティコンテキストを検討しました。
検討の結果対応としてセキュリティコンテキストをtomcat_log_tに変更したところ、エラーは発生せずログのローテートに成功しました。
# chcon --no-dereference -t tomcat_log_t /var/opt/osstech/lib/tomcat/data/openam/openam/{stats,debug}
# runcon system_u:system_r:logrotate_t:s0 /usr/sbin/logrotate -vd /opt/osstech/etc/logrotate.d/openam
WARNING: logrotate in debug mode does nothing except printing debug messages! Consider using verbose mode (-v) instead if this is not what you want.
reading config file /opt/osstech/etc/logrotate.d/openam
olddir is now old
〜
なぜメモリを確保出来ない？
セキュリティコンテキストの変更でエラーは解消されました。
しかし、シンボリックリンクをread出来ないことのエラーメッセージが何故 cannot allocate memory となるのか疑問でした。
通常は権限エラーになると思い、気になったのでlogrotateのソースコードを確認しました。
エラーメッセージに readConfigFile():1806 とあるので、その付近のソースコードを確認します。
- config.c
948 static int readConfigFile(const char *configFile, struct logInfo *defConfig)
949 {
〜
1769 newlog->files = NULL;
1770 newlog->numFiles = 0;
1771 for (argNum = 0; argNum < argc; argNum++) {
1772 char **tmp;
1773 int rc;
1774 glob_t globResult;
1775
1776 if (globerr_msg) {
1777 free(globerr_msg);
1778 globerr_msg = NULL;
1779 }
1780
1781 rc = glob(argv[argNum], GLOB_NOCHECK
1782 #ifdef GLOB_TILDE
1783 | GLOB_TILDE
1784 #endif
1785 , globerr, &globResult);
1786 if (rc == GLOB_ABORTED) {
1787 if (newlog->flags & LOG_FLAG_MISSINGOK) {
1788 continue;
1789 }
1790
1791 /* We don't yet know whether this stanza has "missingok"
1792 * set, so store the error message for later. */
1793 rc = asprintf(&globerr_msg, "%s:%d glob failed for %s: %s\n",
1794 configFile, lineNum, argv[argNum], strerror(glob_errno));
1795 if (rc == -1)
1796 globerr_msg = NULL;
1797
1798 globResult.gl_pathc = 0;
1799 }
1800
1801 tmp = realloc(newlog->files,
1802 sizeof(*newlog->files) * (newlog->numFiles +
1803 globResult.
1804 gl_pathc));
1805 if (tmp == NULL) {
1806 message_OOM();
1807 logerror = 1;
1808 goto duperror;
1809 }
1806行目のmessage_OOM() が今回のエラーを出力している行です。
1801行目realloc(3)の戻り値が NULL の場合に発生することがわかりました。
メモリが不足していれば、領域を確保できず realloc(3)が NULL を返すことはありえます。
しかし、今回の事象発生時にサーバーのメモリは不足していません。
realloc(3)でいくつのメモリを確保しようとしているか調べるため、1800行目に下記のコードを足しました。
fprintf(stderr,"size1:[%d] * (size2:[%d] + size3:[%d])\n", sizeof(*newlog->files), newlog->numFiles, globResult.gl_pathc);
デバッグコードを足したlogrotateをビルドしエラーを再現すると、下記の出力となりました。
reading config file /opt/osstech/etc/logrotate.d/openam
size1:[8] * (size2:[0] + size3:[0])
size1:[8] * (size2:[0] + size3:[0])
error: cannot allocate memory [readConfigFile():1806]
newlog->numFiles と globResult.gl_pathc が共に 0 です。これによって realloc(3)で確保するサイズが 0 です。
また realloc(3) は2回実行されていて、2回目の実行の戻り値が NULL になっていることがわかりました。
社内で教えてもらいましたが、realloc(3) の引数のサイズに 0 を指定してはいけません。1
手元のglibc環境で次のようなコードを書いて試したところ2回目の realloc(3) が NULL になることを確認しました。 logrotate でエラーが起きている状況を再現できました。
- realloc(3) が NULL返すサンプルコード
#include <stdlib.h>
#include <stdio.h>
void null_check(char *tmp){
if( tmp == NULL ){
printf("Param is NULL!!!!\n");
} else {
printf("Param is not NULL\n");
}
}
int main(int argc, char** argv){
char *buf1 = NULL;
char *buf2 = NULL;
buf2 = realloc(buf1, 0);
null_check(buf2);
buf1 = realloc(buf2, 0);
null_check(buf1);
}
- 実行結果
# ./a.out
Param is not NULL
Param is NULL!!!!
realloc(3) の確保するサイズが 0 で、2回実行するとcannot allocate memoryになることがわかりました。
logrotate のソースコードに戻り realloc(3) の確保するサイズが 0 になる理由を調べます。
理由は newlog->numFiles と globResult.gl_pathc が 0 だからですが、これが SELinux が原因で起きていました。
globResult.gl_pathc は 1781行目の glob(3) の結果です。
glob(3)はパターンにマッチするパス名を見付けるライブラリ関数です。
SELinux によりシンボリックリンクを辿れずパターンにマッチするパス名を見つけらずGLOB_ABORTEDがreturnされていました。
1786行目の if文が真になり
1798行目で globResult.gl_pathc に 0 がセットされます。
newlog->numFilesは初期値 0 で、今回引用したコードより後の処理でglobResult.gl_pathcの数だけ + されます。
globResult.gl_pathc が 0 のため、newlog->numFilesは 0 のままとなります。
realloc(3) が2回実行されるのは 1771行目の for文で、これは
ログローテートの設定で指定しているファイルパスの数だけ繰り返します。
今回設定ファイルではstats,debugと２つ指定していました。
試しにstatsのみとしfor文を1回しか繰り返さないようにしたら、
cannot allocate memoryのエラーは発生しませんでした。
事象をまとめると次のとおりです。
- SELinuxが原因で glob(3) がエラーになった。
- glob(3) がエラーになったことに起因してrealloc(3) の確保するサイズが 0 になった
- realloc(3) が2回繰り返すと戻り値が NULL になり、
cannot allocate memoryエラーになった - glob(3) のエラー時の考慮が不足しておりlogrotateのバグ
理由がわかってスッキリ
logrotate が失敗したとき、SELinux が原因というのはすぐ気がつけました。
そのエラーメッセージがcannot allocate memoryで気持ち悪かったのですが、
なぜこのようになったのかを理解出来て非常にスッキリしました。
「realloc 0 サイズ指定」でググると面白い記事見つかります。 ↩︎