PostgreSQL x PAM x syslog

DBへのアクセスにPAMを使うように設定したんだけど、どうも不可解なログを残す。

Jun 20 06:33:19 cosmos .168.2.201(50039) authentication: pam_succeed_if: require
ment "user ingroup db" was met by user "tagoh"

まずpam_succeed_if.soがどんな感じでsyslogにログを吐いているかを見てみた。

int
pam_sm_authenticate(pam_handle_t *pamh, int flags, int argc, const char **argv)
{
...
if(!quiet_succ)
log_error(LOG_INFO,
"requirement \"%s %s %s\" "
"was met by user \"%s\"",
left, qual, right, user);
...
}

そしてlog_error()が

#define MODULE "pam_succeed_if"

...

static void
log_error(int priority, const char *fmt, ...)
{
va_list va;
char *fmt2;
fmt2 = malloc(strlen(fmt) + strlen(MODULE) + 3);
va_start(va, fmt);
if (fmt2 == NULL) {
vsyslog(LOG_AUTHPRIV | priority, fmt, va);
} else {
snprintf(fmt2, strlen(fmt) + strlen(MODULE) + 3,
"%s: %s", MODULE, fmt);
vsyslog(LOG_AUTHPRIV | priority, fmt2, va);
free(fmt2);
}
va_end(va);
}

という具合になっている。このことから、実際にpam_succeed_if.soがsyslogに対して送っているのはpam_succeed_if: ...以降。日付およびホスト名はその先で勝手につけられる。問題はどのプロセスがそれを送ってよこしたのか、という部分なんだけど、.168.2.201(50039) authentication:はどうみてもなんかおかしい。

ということで、次にvsyslog(3)を覗いてみることにする。

static const char *LogTag; /* string to tag the entry with */
...
extern char *__progname; /* Program name, from crt0. */
...
void
vsyslog(pri, fmt, ap)
int pri;
register const char *fmt;
va_list ap;
{
...
if (LogTag == NULL)
LogTag = __progname;
if (LogTag != NULL)
fputs_unlocked (LogTag, f);
if (LogStat & LOG_PID)
fprintf (f, "[%d]", (int) __getpid ());
if (LogTag != NULL)
{
putc_unlocked (':', f);
putc_unlocked (' ', f);
}
/* Restore errno for %m format. */
__set_errno (saved_errno);
/* We have the header. Print the user's format into the
buffer. */
vfprintf (f, fmt, ap);
/* Close the memory stream; this will finalize the data
into a malloc'd buffer in BUF. */
fclose (f);
...
static void
internal_function
openlog_internal(const char *ident, int logstat, int logfac)
{
if (ident != NULL)
LogTag = ident;
...
}

とこんな感じになっていて、openlog(3)されていない場合はそのプログラムの名前を使いましょう、ということになっている。で、pam_succeed_if.soの方はと言うと、openlog(3)は一切使っていない。よってPAMを呼び出したアプリケーション依存ということになる。

では、次にPostgreSQLの方はというとopenlog(3)を呼んでいるのは一箇所のみ。backend/utils/error/elog.c内のwrite_syslog()。

static void
write_syslog(int level, const char *line)
{
static unsigned long seq = 0;
int len;
/* Open syslog connection if not done yet */
if (!openlog_done)
{
openlog(syslog_ident ? syslog_ident : "postgres",
LOG_PID | LOG_NDELAY | LOG_NOWAIT,
syslog_facility);
openlog_done = true;
}
...

つまり、一度もsyslogへログを吐こうとしてなければopenlog(3)は呼ばれない。

postgresql.confの中にlog_destinationというパラメータがあって(少なくともDebian環境上では)デフォルトがstderrになっている。根本的な解決方法としては、これによらずopenlog(3)を呼べ、ということになるんだけど、手っ取り早くworkaroundで済ますなら、このlog_destinationをsyslogに変える。そうすると

Jun 20 23:52:07 cosmos postgres[9371]: pam_succeed_if: requirement "user ingroup
db" was met by user "tagoh"

という具合に期待どおりの結果になった。