Sys::Syslog writes to /dev/console instead of /dev/log

[Stuart Kendrick]

hi,

i have a script which does work, sleeps for thirty seconds, stats a
file (and if the timestamp on that file has changed since the last
time it looked, it logs a message to syslog (and then opens the file
and reads it)) ... and then does work, sleeps for thirty seconds ...
ad infinitum.

most of the time, all this goes according to plan. but sometimes, the
script slips into a state where it doesn't log anything to syslog.
from the strace output, i can see that it tries to log to /dev/console
instead.

perl-5.8.3 (w/threading), SuSE 8.2

the relevant code is here:

[...]
use Sys::Syslog;
[...]
openlog('nodewatch', '', 'info');
syslog('info', 'Reading node database');
closelog();
[...]

and here is strace output from a functioning case and then from a
pathological case:

functioning case:
[...]
stat64("/opt/vdops/etc/nodewatch/nodewatch.nodes",
{st_mode=S_IFREG|0660, st_siz
e=20194, ...}) = 0
socket(PF_UNIX, SOCK_STREAM, 0) = 3
ioctl(3, SNDCTL_TMR_TIMEBASE, 0xbfffe4b0) = -1 EINVAL (Invalid
argument)
_llseek(3, 0, 0xbfffe510, SEEK_CUR) = -1 ESPIPE (Illegal seek)
ioctl(3, SNDCTL_TMR_TIMEBASE, 0xbfffe4b0) = -1 EINVAL (Invalid
argument)
_llseek(3, 0, 0xbfffe510, SEEK_CUR) = -1 ESPIPE (Illegal seek)
fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
connect(3, {sa_family=AF_UNIX, path="/dev/log"}, 110) = -1 EPROTOTYPE
(Protocol
wrong type for socket)
close(3) = 0
socket(PF_UNIX, SOCK_DGRAM, 0) = 3
ioctl(3, SNDCTL_TMR_TIMEBASE, 0xbfffe4b0) = -1 EINVAL (Invalid
argument)
_llseek(3, 0, 0xbfffe510, SEEK_CUR) = -1 ESPIPE (Illegal seek)
ioctl(3, SNDCTL_TMR_TIMEBASE, 0xbfffe4b0) = -1 EINVAL (Invalid
argument)
_llseek(3, 0, 0xbfffe510, SEEK_CUR) = -1 ESPIPE (Illegal seek)
fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
connect(3, {sa_family=AF_UNIX, path="/dev/log"}, 110) = 0
select(8, [3], NULL, [3], {0, 0}) = 0 (Timeout)
write(3, "<134>nodewatch: Reading node dat"..., 39) = 39
close(3) = 0
stat64("/opt/vdops/etc/nodewatch/nodewatch.nodes",
{st_mode=S_IFREG|0660, st_siz
e=20194, ...}) = 0
open("/opt/vdops/etc/nodewatch/nodewatch.nodes", O_RDONLY|O_LARGEFILE)
= 3
ioctl(3, SNDCTL_TMR_TIMEBASE, 0xbfffe330) = -1 ENOTTY (Inappropriate
ioctl for d
evice)_llseek(3, 0, [0], SEEK_CUR) = 0
fstat64(3, {st_mode=S_IFREG|0660, st_size=20194, ...}) = 0
fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
read(3, "offhour\nja-a-rtr\t\tc\t2\t1\tvdops:wo"..., 4096) = 4096
[...]

pathological case:
[...]
stat64("/opt/vdops/etc/nodewatch/nodewatch.nodes",
{st_mode=S_IFREG|0660, st_siz
e=20194, ...}) = 0
stat64("/dev/console", {st_mode=S_IFCHR|0600, st_rdev=makedev(5, 1),
....}) = 0
fork() = 17333
wait4(17333, [WIFEXITED(s) && WEXITSTATUS(s) == 1], 0, NULL) = 17333
--- SIGCHLD (Child exited) @ 0 (0) ---
stat64("/opt/vdops/etc/nodewatch/nodewatch.nodes",
{st_mode=S_IFREG|0660, st_siz
e=20194, ...}) = 0
open("/opt/vdops/etc/nodewatch/nodewatch.nodes", O_RDONLY|O_LARGEFILE)
= 3
ioctl(3, SNDCTL_TMR_TIMEBASE, 0xbfffe4f0) = -1 ENOTTY (Inappropriate
ioctl for d
evice)_llseek(3, 0, [0], SEEK_CUR) = 0
fstat64(3, {st_mode=S_IFREG|0660, st_size=20194, ...}) = 0
fcntl64(3, F_SETFD, FD_CLOEXEC) = 0
read(3, "offhour\nja-a-rtr\t\tc\t2\t1\tvdops:wo"..., 4096) = 4096
[...]


my questions:

-has anyone seen this before? where Sys::Syslog starts logging to
/dev/console instead of to /dev/log?

-any idea why Perl performs all these sound card ioctl calls? [e.g.
ioctl(3, SNDCTL_TMR_TIMEBASE, 0xbfffe4f0) = -1 ENOTTY (Inappropriate
ioctl for device)_llseek(3, 0, [0], SEEK_CUR)] (though, since this
seems to be a red herring ... cosmetic issue ... perhaps i don't want
to go there ... )


insights appreciated.


--sk

Stuart Kendrick
FHCRC