Re: [syslog-ng] Redirect syslog-ng to ttyS0
Hei. I have included the strace log ( when I log in n ttyS0). Can anyone help me analyzing it. Kjell execve("/sbin/syslog-ng", ["syslog-ng"], [/* 69 vars */]) = 0 brk(0) = 0x80021000 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f79000 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) open("/etc/ld.so.cache", O_RDONLY) = 3 fstat64(3, {st_mode=S_IFREG|0644, st_size=82152, ...}) = 0 mmap2(NULL, 82152, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7f64000 close(3) = 0 open("/lib/libnsl.so.1", O_RDONLY) = 3 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0`5\0\000"..., 512) = 512 fstat64(3, {st_mode=S_IFREG|0755, st_size=87850, ...}) = 0 mmap2(NULL, 83712, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7f4f000 madvise(0xb7f4f000, 83712, MADV_SEQUENTIAL|0x1) = 0 mmap2(0xb7f60000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x10) = 0xb7f60000 mmap2(0xb7f62000, 5888, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7f62000 close(3) = 0 open("/lib/libresolv.so.2", O_RDONLY) = 3 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0P&\0\000"..., 512) = 512 fstat64(3, {st_mode=S_IFREG|0755, st_size=74278, ...}) = 0 mmap2(NULL, 76052, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7f3c000 madvise(0xb7f3c000, 76052, MADV_SEQUENTIAL|0x1) = 0 mmap2(0xb7f4b000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xe) = 0xb7f4b000 mmap2(0xb7f4d000, 6420, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7f4d000 close(3) = 0 open("/lib/libc.so.6", O_RDONLY) = 3 read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\300Y\1"..., 512) = 512 fstat64(3, {st_mode=S_IFREG|0755, st_size=1408371, ...}) = 0 mmap2(NULL, 1181084, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7e1b000 madvise(0xb7e1b000, 1181084, MADV_SEQUENTIAL|0x1) = 0 mmap2(0xb7f35000, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x119) = 0xb7f35000 mmap2(0xb7f39000, 9628, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7f39000 close(3) = 0 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7e1a000 set_thread_area({entry_number:-1 -> 6, base_addr:0xb7e1a8c0, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0 mprotect(0xb7f35000, 8192, PROT_READ) = 0 munmap(0xb7f64000, 82152) = 0 brk(0) = 0x80021000 brk(0x80042000) = 0x80042000 open("/etc/localtime", O_RDONLY) = 3 fstat64(3, {st_mode=S_IFREG|0644, st_size=56, ...}) = 0 fstat64(3, {st_mode=S_IFREG|0644, st_size=56, ...}) = 0 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f78000 read(3, "TZif\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\1\0\0\0\1\0"..., 4096) = 56 close(3) = 0 munmap(0xb7f78000, 4096) = 0 open("/etc/syslog-ng/syslog-ng.conf", O_RDONLY) = 3 ioctl(3, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbfec3f78) = -1 ENOTTY (Inappropriate ioctl for device) fstat64(3, {st_mode=S_IFREG|0644, st_size=5785, ...}) = 0 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f78000 read(3, "#\n# /etc/syslog-ng/syslog-ng.con"..., 8192) = 5785 read(3, "", 4096) = 0 socket(PF_FILE, SOCK_STREAM, 0) = 4 fcntl64(4, F_GETFL) = 0x2 (flags O_RDWR) fcntl64(4, F_SETFL, O_RDWR|O_NONBLOCK) = 0 connect(4, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory) close(4) = 0 socket(PF_FILE, SOCK_STREAM, 0) = 4 fcntl64(4, F_GETFL) = 0x2 (flags O_RDWR) fcntl64(4, F_SETFL, O_RDWR|O_NONBLOCK) = 0 connect(4, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory) close(4) = 0 open("/etc/nsswitch.conf", O_RDONLY) = 4 fstat64(4, {st_mode=S_IFREG|0644, st_size=1185, ...}) = 0 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f77000 read(4, "#\n# /etc/nsswitch.conf\n#\n# An ex"..., 4096) = 1185 read(4, "", 4096) = 0 close(4) = 0 munmap(0xb7f77000, 4096) = 0 open("/etc/ld.so.cache", O_RDONLY) = 4 fstat64(4, {st_mode=S_IFREG|0644, st_size=82152, ...}) = 0 mmap2(NULL, 82152, PROT_READ, MAP_PRIVATE, 4, 0) = 0xb7e05000 close(4) = 0 open("/lib/libnss_compat.so.2", O_RDONLY) = 4 read(4, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0@\21\0\000"..., 512) = 512 fstat64(4, {st_mode=S_IFREG|0755, st_size=31943, ...}) = 0 mmap2(NULL, 29296, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 4, 0) = 0xb7f70000 madvise(0xb7f70000, 29296, MADV_SEQUENTIAL|0x1) = 0 mmap2(0xb7f76000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 4, 0x5) = 0xb7f76000 close(4) = 0 munmap(0xb7e05000, 82152) = 0 open("/etc/ld.so.cache", O_RDONLY) = 4 fstat64(4, {st_mode=S_IFREG|0644, st_size=82152, ...}) = 0 mmap2(NULL, 82152, PROT_READ, MAP_PRIVATE, 4, 0) = 0xb7e05000 close(4) = 0 open("/lib/libnss_nis.so.2", O_RDONLY) = 4 read(4, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\260\34"..., 512) = 512 fstat64(4, {st_mode=S_IFREG|0755, st_size=41986, ...}) = 0 mmap2(NULL, 37424, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 4, 0) = 0xb7f66000 madvise(0xb7f66000, 37424, MADV_SEQUENTIAL|0x1) = 0 mmap2(0xb7f6e000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 4, 0x7) = 0xb7f6e000 close(4) = 0 open("/lib/libnss_files.so.2", O_RDONLY) = 4 read(4, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\360\33"..., 512) = 512 fstat64(4, {st_mode=S_IFREG|0755, st_size=42109, ...}) = 0 mmap2(NULL, 37528, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 4, 0) = 0xb7dfb000 madvise(0xb7dfb000, 37528, MADV_SEQUENTIAL|0x1) = 0 mmap2(0xb7e03000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 4, 0x7) = 0xb7e03000 close(4) = 0 munmap(0xb7e05000, 82152) = 0 open("/etc/group", O_RDONLY) = 4 fcntl64(4, F_GETFD) = 0 fcntl64(4, F_SETFD, FD_CLOEXEC) = 0 _llseek(4, 0, [0], SEEK_CUR) = 0 fstat64(4, {st_mode=S_IFREG|0644, st_size=831, ...}) = 0 mmap2(NULL, 831, PROT_READ, MAP_SHARED, 4, 0) = 0xb7e19000 _llseek(4, 831, [831], SEEK_SET) = 0 munmap(0xb7e19000, 831) = 0 close(4) = 0 open("/etc/group", O_RDONLY) = 4 fcntl64(4, F_GETFD) = 0 fcntl64(4, F_SETFD, FD_CLOEXEC) = 0 _llseek(4, 0, [0], SEEK_CUR) = 0 fstat64(4, {st_mode=S_IFREG|0644, st_size=831, ...}) = 0 mmap2(NULL, 831, PROT_READ, MAP_SHARED, 4, 0) = 0xb7e19000 _llseek(4, 831, [831], SEEK_SET) = 0 munmap(0xb7e19000, 831) = 0 close(4) = 0 socket(PF_FILE, SOCK_STREAM, 0) = 4 fcntl64(4, F_GETFL) = 0x2 (flags O_RDWR) fcntl64(4, F_SETFL, O_RDWR|O_NONBLOCK) = 0 connect(4, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory) close(4) = 0 socket(PF_FILE, SOCK_STREAM, 0) = 4 fcntl64(4, F_GETFL) = 0x2 (flags O_RDWR) fcntl64(4, F_SETFL, O_RDWR|O_NONBLOCK) = 0 connect(4, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory) close(4) = 0 open("/etc/passwd", O_RDONLY) = 4 fcntl64(4, F_GETFD) = 0 fcntl64(4, F_SETFD, FD_CLOEXEC) = 0 _llseek(4, 0, [0], SEEK_CUR) = 0 fstat64(4, {st_mode=S_IFREG|0644, st_size=1654, ...}) = 0 mmap2(NULL, 1654, PROT_READ, MAP_SHARED, 4, 0) = 0xb7e19000 _llseek(4, 1654, [1654], SEEK_SET) = 0 munmap(0xb7e19000, 1654) = 0 close(4) = 0 open("/etc/group", O_RDONLY) = 4 fcntl64(4, F_GETFD) = 0 fcntl64(4, F_SETFD, FD_CLOEXEC) = 0 _llseek(4, 0, [0], SEEK_CUR) = 0 fstat64(4, {st_mode=S_IFREG|0644, st_size=831, ...}) = 0 mmap2(NULL, 831, PROT_READ, MAP_SHARED, 4, 0) = 0xb7e19000 _llseek(4, 831, [831], SEEK_SET) = 0 munmap(0xb7e19000, 831) = 0 close(4) = 0 open("/etc/passwd", O_RDONLY) = 4 fcntl64(4, F_GETFD) = 0 fcntl64(4, F_SETFD, FD_CLOEXEC) = 0 _llseek(4, 0, [0], SEEK_CUR) = 0 fstat64(4, {st_mode=S_IFREG|0644, st_size=1654, ...}) = 0 mmap2(NULL, 1654, PROT_READ, MAP_SHARED, 4, 0) = 0xb7e19000 _llseek(4, 1654, [1654], SEEK_SET) = 0 munmap(0xb7e19000, 1654) = 0 close(4) = 0 open("/etc/group", O_RDONLY) = 4 fcntl64(4, F_GETFD) = 0 fcntl64(4, F_SETFD, FD_CLOEXEC) = 0 _llseek(4, 0, [0], SEEK_CUR) = 0 fstat64(4, {st_mode=S_IFREG|0644, st_size=831, ...}) = 0 mmap2(NULL, 831, PROT_READ, MAP_SHARED, 4, 0) = 0xb7e19000 _llseek(4, 831, [831], SEEK_SET) = 0 munmap(0xb7e19000, 831) = 0 close(4) = 0 open("/etc/passwd", O_RDONLY) = 4 fcntl64(4, F_GETFD) = 0 fcntl64(4, F_SETFD, FD_CLOEXEC) = 0 _llseek(4, 0, [0], SEEK_CUR) = 0 fstat64(4, {st_mode=S_IFREG|0644, st_size=1654, ...}) = 0 mmap2(NULL, 1654, PROT_READ, MAP_SHARED, 4, 0) = 0xb7e19000 _llseek(4, 1654, [1654], SEEK_SET) = 0 munmap(0xb7e19000, 1654) = 0 close(4) = 0 open("/etc/group", O_RDONLY) = 4 fcntl64(4, F_GETFD) = 0 fcntl64(4, F_SETFD, FD_CLOEXEC) = 0 _llseek(4, 0, [0], SEEK_CUR) = 0 fstat64(4, {st_mode=S_IFREG|0644, st_size=831, ...}) = 0 mmap2(NULL, 831, PROT_READ, MAP_SHARED, 4, 0) = 0xb7e19000 _llseek(4, 831, [831], SEEK_SET) = 0 munmap(0xb7e19000, 831) = 0 close(4) = 0 read(3, "", 8192) = 0 ioctl(3, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbfec39f8) = -1 ENOTTY (Inappropriate ioctl for device) close(3) = 0 munmap(0xb7f78000, 4096) = 0 pipe([3, 4]) = 0 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb7e1a908) = 5189 close(4) = 0 read(3, "\0", 1) = 1 exit_group(0) = ?
On Tue, 2007-11-13 at 12:24 +0100, kjell.danielsen@hjemme.no wrote:
Hei.
I have included the strace log ( when I log in n ttyS0). Can anyone help me analyzing it.
you need to attach to syslog-ng once it is running and actually writing messages to ttyS0. What you strace-ed here is the startup of syslog-ng, not the way it works when you log in. This dump is unusable.
Kjell
-- Bazsi
On Tue, 13 Nov 2007 12:24:26 +0100, kjell.danielsen@hjemme.no said:
Hei.
I have included the strace log ( when I log in n ttyS0). Can anyone help me analyzing it.
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb7e1a908) = 5189
You want to either attach strace to an already running syslog-ng by using 'strace -p PID', or tell strace to try to follow forks by using 'strace -f'.
Here is a new trace. I start the trace before I logged in on ttyS0. After I logged in the syslog output to ttyS0 stops, and I have to restart the server to get the syslog output on ttyS0. Kjell time(NULL) = 1195026575 poll([{fd=13, events=0}, {fd=12, events=0}, {fd=11, events=0}, {fd=10, events=0}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=0}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 11, 100) = 0 poll([{fd=13, events=0}, {fd=12, events=0}, {fd=11, events=0}, {fd=10, events=0}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=0}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN, revents=POLLIN}], 11, 3448000) = 1 recvfrom(3, "<165>Nov 14 07:49:40 AL[3581]: A"..., 2048, 0, {sa_family=AF_UNSPEC, sa_data="\2\200\356E\1\200\0\371\1\200\320\21\2\200"}, [0]) = 187 time(NULL) = 1195026580 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=56, ...}) = 0 time(NULL) = 1195026580 time(NULL) = 1195026580 poll([{fd=13, events=POLLOUT, revents=POLLOUT}, {fd=12, events=0}, {fd=11, events=0}, {fd=10, events=POLLOUT, revents=POLLOUT}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=POLLOUT, revents=POLLOUT}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 11, 100) = 3 write(13, "Nov 14 07:49:40 lim1 AL[3581]: A"..., 188) = 188 write(10, "Nov 14 07:49:40 lim1 AL[3581]: A"..., 188) = 188 write(4, "Nov 14 07:49:40 lim1 AL[3581]: A"..., 188) = 188 time(NULL) = 1195026580 poll([{fd=13, events=0}, {fd=12, events=0}, {fd=11, events=0}, {fd=10, events=0}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=0}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 11, 100) = 0 poll([{fd=13, events=0}, {fd=12, events=0}, {fd=11, events=0}, {fd=10, events=0}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=0}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN, revents=POLLIN}], 11, 3443000) = 1 recvfrom(3, "<165>Nov 14 07:49:44 AL[3581]: A"..., 2048, 0, {sa_family=AF_UNSPEC, sa_data="\2\200\356E\1\200\0\371\1\200\320\21\2\200"}, [0]) = 56 time(NULL) = 1195026584 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=56, ...}) = 0 time(NULL) = 1195026584 time(NULL) = 1195026584 poll([{fd=13, events=POLLOUT, revents=POLLOUT}, {fd=12, events=0}, {fd=11, events=0}, {fd=10, events=POLLOUT, revents=POLLOUT}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=POLLOUT, revents=POLLOUT}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 11, 100) = 3 write(13, "Nov 14 07:49:44 lim1 AL[3581]: A"..., 57) = 57 write(10, "Nov 14 07:49:44 lim1 AL[3581]: A"..., 57) = 57 write(4, "Nov 14 07:49:44 lim1 AL[3581]: A"..., 57) = 57 time(NULL) = 1195026584 poll([{fd=13, events=0}, {fd=12, events=0}, {fd=11, events=0}, {fd=10, events=0}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=0}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 11, 100) = 0 poll([{fd=13, events=0, revents=POLLERR|POLLHUP}, {fd=12, events=0}, {fd=11, events=0}, {fd=10, events=0}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=0}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 11, 3439000) = 1 time(NULL) = 1195026596 close(13) = 0 poll([{fd=12, events=0}, {fd=11, events=0}, {fd=10, events=0}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=0}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 10, 100) = 0 poll([{fd=12, events=0}, {fd=11, events=0}, {fd=10, events=0}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=0}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN, revents=POLLIN}], 10, 3427000) = 1 recvfrom(3, "<181>Nov 14 07:50:00 mdsh[5063]:"..., 2048, 0, {sa_family=AF_UNSPEC, sa_data="\200\277\'F\1\200\0\371\1\200\320\21\2\200"}, [0]) = 155 time(NULL) = 1195026600 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=56, ...}) = 0 time(NULL) = 1195026600 time(NULL) = 1195026600 poll([{fd=12, events=0}, {fd=11, events=0}, {fd=10, events=POLLOUT, revents=POLLOUT}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=POLLOUT, revents=POLLOUT}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 10, 100) = 2 write(10, "Nov 14 07:50:00 lim1 mdsh[5063]:"..., 156) = 156 write(4, "Nov 14 07:50:00 lim1 mdsh[5063]:"..., 156) = 156 time(NULL) = 1195026600 poll([{fd=12, events=0}, {fd=11, events=0}, {fd=10, events=0}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=0}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN, revents=POLLIN}], 10, 100) = 1 recvfrom(3, "<181>Nov 14 07:50:00 mdsh[5063]:"..., 2048, 0, {sa_family=AF_UNSPEC, sa_data="\200\277\'F\1\200\0\371\1\200\320\21\2\200"}, [0]) = 165 time(NULL) = 1195026600 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=56, ...}) = 0 time(NULL) = 1195026600 time(NULL) = 1195026600 poll([{fd=12, events=0}, {fd=11, events=0}, {fd=10, events=POLLOUT, revents=POLLOUT}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=POLLOUT, revents=POLLOUT}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN, revents=POLLIN}], 10, 100) = 3 write(10, "Nov 14 07:50:00 lim1 mdsh[5063]:"..., 166) = 166 write(4, "Nov 14 07:50:00 lim1 mdsh[5063]:"..., 166) = 166 recvfrom(3, "<181>Nov 14 07:50:00 mdsh[5063]:"..., 2048, 0, {sa_family=AF_UNSPEC, sa_data="\200\277\'F\1\200\0\371\1\200\320\21\2\200"}, [0]) = 51 time(NULL) = 1195026600 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=56, ...}) = 0 time(NULL) = 1195026600 time(NULL) = 1195026600 poll([{fd=12, events=0}, {fd=11, events=0}, {fd=10, events=POLLOUT, revents=POLLOUT}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=POLLOUT, revents=POLLOUT}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 10, 100) = 2 write(10, "Nov 14 07:50:00 lim1 mdsh[5063]:"..., 52) = 52 write(4, "Nov 14 07:50:00 lim1 mdsh[5063]:"..., 52) = 52 time(NULL) = 1195026600 poll([{fd=12, events=0}, {fd=11, events=0}, {fd=10, events=0}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=0}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN, revents=POLLIN}], 10, 100) = 1 recvfrom(3, "<181>Nov 14 07:50:00 mdsh[5063]:"..., 2048, 0, {sa_family=AF_UNSPEC, sa_data="\200\277\'F\1\200\0\371\1\200\320\21\2\200"}, [0]) = 61 time(NULL) = 1195026600 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=56, ...}) = 0 time(NULL) = 1195026600 time(NULL) = 1195026600 poll([{fd=12, events=0}, {fd=11, events=0}, {fd=10, events=POLLOUT, revents=POLLOUT}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=POLLOUT, revents=POLLOUT}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN, revents=POLLIN}], 10, 100) = 3 write(10, "Nov 14 07:50:00 lim1 mdsh[5063]:"..., 62) = 62 write(4, "Nov 14 07:50:00 lim1 mdsh[5063]:"..., 62) = 62 recvfrom(3, "<181>Nov 14 07:50:00 mdsh[5063]:"..., 2048, 0, {sa_family=AF_UNSPEC, sa_data="\200\277\'F\1\200\0\371\1\200\320\21\2\200"}, [0]) = 126 time(NULL) = 1195026600 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=56, ...}) = 0 time(NULL) = 1195026600 time(NULL) = 1195026600 poll([{fd=12, events=0}, {fd=11, events=0}, {fd=10, events=POLLOUT, revents=POLLOUT}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=POLLOUT, revents=POLLOUT}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 10, 100) = 2 write(10, "Nov 14 07:50:00 lim1 mdsh[5063]:"..., 127) = 127 write(4, "Nov 14 07:50:00 lim1 mdsh[5063]:"..., 127) = 127 time(NULL) = 1195026600 poll([{fd=12, events=0}, {fd=11, events=0}, {fd=10, events=0}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=0}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN, revents=POLLIN}], 10, 100) = 1 recvfrom(3, "<181>Nov 14 07:50:00 mdsh[5063]:"..., 2048, 0, {sa_family=AF_UNSPEC, sa_data="\200\277\'F\1\200\0\371\1\200\320\21\2\200"}, [0]) = 136 time(NULL) = 1195026600 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=56, ...}) = 0 time(NULL) = 1195026600 time(NULL) = 1195026600 poll([{fd=12, events=0}, {fd=11, events=0}, {fd=10, events=POLLOUT, revents=POLLOUT}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=POLLOUT, revents=POLLOUT}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN, revents=POLLIN}], 10, 100) = 3 write(10, "Nov 14 07:50:00 lim1 mdsh[5063]:"..., 137) = 137 write(4, "Nov 14 07:50:00 lim1 mdsh[5063]:"..., 137) = 137 recvfrom(3, "<181>Nov 14 07:50:00 mdsh[5063]:"..., 2048, 0, {sa_family=AF_UNSPEC, sa_data="\200\277\'F\1\200\0\371\1\200\320\21\2\200"}, [0]) = 51 time(NULL) = 1195026600 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=56, ...}) = 0 time(NULL) = 1195026600 time(NULL) = 1195026600 poll([{fd=12, events=0}, {fd=11, events=0}, {fd=10, events=POLLOUT, revents=POLLOUT}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=POLLOUT, revents=POLLOUT}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 10, 100) = 2 write(10, "Nov 14 07:50:00 lim1 mdsh[5063]:"..., 52) = 52 write(4, "Nov 14 07:50:00 lim1 mdsh[5063]:"..., 52) = 52 time(NULL) = 1195026600 poll([{fd=12, events=0}, {fd=11, events=0}, {fd=10, events=0}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=0}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN, revents=POLLIN}], 10, 100) = 1 recvfrom(3, "<181>Nov 14 07:50:00 mdsh[5063]:"..., 2048, 0, {sa_family=AF_UNSPEC, sa_data="\200\277\'F\1\200\0\371\1\200\320\21\2\200"}, [0]) = 61 time(NULL) = 1195026600 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=56, ...}) = 0 time(NULL) = 1195026600 time(NULL) = 1195026600 poll([{fd=12, events=0}, {fd=11, events=0}, {fd=10, events=POLLOUT, revents=POLLOUT}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=POLLOUT, revents=POLLOUT}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN, revents=POLLIN}], 10, 100) = 3 write(10, "Nov 14 07:50:00 lim1 mdsh[5063]:"..., 62) = 62 write(4, "Nov 14 07:50:00 lim1 mdsh[5063]:"..., 62) = 62 recvfrom(3, "<181>Nov 14 07:50:00 mdsh[5063]:"..., 2048, 0, {sa_family=AF_UNSPEC, sa_data="\200\277\'F\1\200\0\371\1\200\320\21\2\200"}, [0]) = 148 time(NULL) = 1195026600 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=56, ...}) = 0 time(NULL) = 1195026600 time(NULL) = 1195026600 poll([{fd=12, events=0}, {fd=11, events=0}, {fd=10, events=POLLOUT, revents=POLLOUT}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=POLLOUT, revents=POLLOUT}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 10, 100) = 2 write(10, "Nov 14 07:50:00 lim1 mdsh[5063]:"..., 149) = 149 write(4, "Nov 14 07:50:00 lim1 mdsh[5063]:"..., 149) = 149 time(NULL) = 1195026600 poll([{fd=12, events=0}, {fd=11, events=0}, {fd=10, events=0}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=0}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN, revents=POLLIN}], 10, 100) = 1 recvfrom(3, "<181>Nov 14 07:50:00 mdsh[5063]:"..., 2048, 0, {sa_family=AF_UNSPEC, sa_data="\200\277\'F\1\200\0\371\1\200\320\21\2\200"}, [0]) = 158 time(NULL) = 1195026600 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=56, ...}) = 0 time(NULL) = 1195026600 time(NULL) = 1195026600 poll([{fd=12, events=0}, {fd=11, events=0}, {fd=10, events=POLLOUT, revents=POLLOUT}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=POLLOUT, revents=POLLOUT}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 10, 100) = 2 write(10, "Nov 14 07:50:00 lim1 mdsh[5063]:"..., 159) = 159 write(4, "Nov 14 07:50:00 lim1 mdsh[5063]:"..., 159) = 159 time(NULL) = 1195026600 poll([{fd=12, events=0}, {fd=11, events=0}, {fd=10, events=0}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=0}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 10, 100) = 0 poll([{fd=12, events=0}, {fd=11, events=0}, {fd=10, events=0}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=0}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN, revents=POLLIN}], 10, 3423000) = 1 recvfrom(3, "<165>Nov 14 07:50:05 AL[3581]: A"..., 2048, 0, {sa_family=AF_UNSPEC, sa_data="\200\277\'F\1\200\0\371\1\200\320\21\2\200"}, [0]) = 210 time(NULL) = 1195026605 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=56, ...}) = 0 time(NULL) = 1195026605 time(NULL) = 1195026605 poll([{fd=12, events=0}, {fd=11, events=0}, {fd=10, events=POLLOUT, revents=POLLOUT}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=POLLOUT, revents=POLLOUT}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 10, 100) = 2 write(10, "Nov 14 07:50:05 lim1 AL[3581]: A"..., 211) = 211 write(4, "Nov 14 07:50:05 lim1 AL[3581]: A"..., 211) = 211 time(NULL) = 1195026605 poll([{fd=12, events=0}, {fd=11, events=0}, {fd=10, events=0}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=0}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 10, 100) = 0 poll([{fd=12, events=0}, {fd=11, events=0}, {fd=10, events=0}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=0}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN, revents=POLLIN}], 10, 3418000) = 1 recvfrom(3, "<165>Nov 14 07:50:09 AL[3581]: A"..., 2048, 0, {sa_family=AF_UNSPEC, sa_data="\200\277\'F\1\200\0\371\1\200\320\21\2\200"}, [0]) = 56 time(NULL) = 1195026609 stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=56, ...}) = 0 time(NULL) = 1195026609 time(NULL) = 1195026609 poll([{fd=12, events=0}, {fd=11, events=0}, {fd=10, events=POLLOUT, revents=POLLOUT}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=POLLOUT, revents=POLLOUT}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 10, 100) = 2 write(10, "Nov 14 07:50:09 lim1 AL[3581]: A"..., 57) = 57 write(4, "Nov 14 07:50:09 lim1 AL[3581]: A"..., 57) = 57 time(NULL) = 1195026609 poll([{fd=12, events=0}, {fd=11, events=0}, {fd=10, events=0}, {fd=9, events=0}, {fd=8, events=0}, {fd=7, events=0}, {fd=4, events=0}, {fd=6, events=POLLIN}, {fd=5, events=POLLIN}, {fd=3, events=POLLIN}], 10, 100) = 0 poll( <unfinished ...>
On Sun, 2007-11-18 at 19:39 +0100, Kjell Danielsen wrote:
Here is a new trace. I start the trace before I logged in on ttyS0. After I logged in the syslog output to ttyS0 stops, and I have to restart the server to get the syslog output on ttyS0.
Kjell
the reason syslog-ng stops, because it receives a POLLERR/POLLHUP event in this case: poll([{fd=13, events=0, revents=POLLERR|POLLHUP Hm... did syslog-ng report any kind of error in this case? I'm expecting an msg_error("EOF occurred while idle", evt_tag_int("fd", self->fd->fd), NULL); or, a msg_error("I/O error occurred while writing", evt_tag_int("fd", fd->fd), evt_tag_errno(EVT_TAG_OSERROR, errno), NULL); message. I can't see anything like this in the stace file, but maybe you are not reading the internal() log source? -- Bazsi
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 Jumping in on this thread!
On Sun, 2007-11-18 at 19:39 +0100, Kjell Danielsen wrote:
Here is a new trace. I start the trace before I logged in on ttyS0. After I logged in the syslog output to ttyS0 stops, and I have to restart the server to get the syslog output on ttyS0.
Kjell
the reason syslog-ng stops, because it receives a POLLERR/POLLHUP event in this case:
poll([{fd=13, events=0, revents=POLLERR|POLLHUP
Hm... did syslog-ng report any kind of error in this case? I'm expecting an
msg_error("EOF occurred while idle", evt_tag_int("fd", self->fd->fd), NULL);
or, a
msg_error("I/O error occurred while writing", evt_tag_int("fd", fd->fd), evt_tag_errno(EVT_TAG_OSERROR, errno), NULL);
message. I can't see anything like this in the stace file, but maybe you are not reading the internal() log source?
I am a distant colleague of Kjell and put together a labtest for this case. I can confirm the behaviour and the strace ending with POLLERR/POLLHUP, and no errors given from syslog-ng. I see that syslog-ng changes permissions on /dev/ttyS= and when you log in on the console port 'login' or 'agetty' changes the permissions again causing syslog-ng to stop. Version: 1.6.8-20.4 packaged by Suse. -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.7 (MingW32) Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org iD8DBQFHTXFHsJJnSzEQqpgRAtZXAJwKHNDpDmyYNxlMQDpTZ13wywaZmgCdGBAs xWgQnGb2IfLOuW5QIGSQAk8= =y5A5 -----END PGP SIGNATURE-----
On Wed, 2007-11-28 at 14:46 +0100, Vidar Tyldum Hansen wrote:
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1
Jumping in on this thread!
On Sun, 2007-11-18 at 19:39 +0100, Kjell Danielsen wrote:
Here is a new trace. I start the trace before I logged in on ttyS0. After I logged in the syslog output to ttyS0 stops, and I have to restart the server to get the syslog output on ttyS0.
Kjell
the reason syslog-ng stops, because it receives a POLLERR/POLLHUP event in this case:
poll([{fd=13, events=0, revents=POLLERR|POLLHUP
Hm... did syslog-ng report any kind of error in this case? I'm expecting an
msg_error("EOF occurred while idle", evt_tag_int("fd", self->fd->fd), NULL);
or, a
msg_error("I/O error occurred while writing", evt_tag_int("fd", fd->fd), evt_tag_errno(EVT_TAG_OSERROR, errno), NULL);
message. I can't see anything like this in the stace file, but maybe you are not reading the internal() log source?
I am a distant colleague of Kjell and put together a labtest for this case. I can confirm the behaviour and the strace ending with POLLERR/POLLHUP, and no errors given from syslog-ng.
I see that syslog-ng changes permissions on /dev/ttyS= and when you log in on the console port 'login' or 'agetty' changes the permissions again causing syslog-ng to stop.
I think this is not a permission problem. syslog-ng opens the device once, and then it is kept opened. Permissions checking is usually applied at open time and not any later. -- Bazsi
On Thu, 29 Nov 2007 11:14:12 +0100, Balazs Scheidler said:
I think this is not a permission problem. syslog-ng opens the device once, and then it is kept opened. Permissions checking is usually applied at open time and not any later.
Note that on a Linux box that uses SELinux, it *is* possible for a file to be opened sucessfully, but later on a security context change on the file causes subsequent read/write activity to fail. Before login: % ls -lZ /dev/tty1 crw------- root root system_u:object_r:tty_device_t:s0 /dev/tty1 After login: % ls -lZ /dev/tty1 crw------- valdis tty staff_u:object_r:staff_tty_device_t:s0 /dev/tty1 (This is with SELinux and the MLS stuff in place). My best guess as to what's nuking things - flush_unauthorized_files() in security/hooks.c in the kernel.
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 Valdis.Kletnieks@vt.edu skrev:
On Thu, 29 Nov 2007 11:14:12 +0100, Balazs Scheidler said:
I think this is not a permission problem. syslog-ng opens the device once, and then it is kept opened. Permissions checking is usually applied at open time and not any later.
Note that on a Linux box that uses SELinux, it *is* possible for a file to be opened sucessfully, but later on a security context change on the file causes subsequent read/write activity to fail.
Before login:
% ls -lZ /dev/tty1 crw------- root root system_u:object_r:tty_device_t:s0 /dev/tty1
After login:
% ls -lZ /dev/tty1 crw------- valdis tty staff_u:object_r:staff_tty_device_t:s0 /dev/tty1
(This is with SELinux and the MLS stuff in place).
My best guess as to what's nuking things - flush_unauthorized_files() in security/hooks.c in the kernel.
This is Suse Enterprise Linux 10 (tailored for Ericsson PBX), and there you have not SELinux, but AppArmor. That might provide the same mechanism and be the culprit. Also explains why the behaviour does not seem obvious to someonw who knows the syslog-ng codebase. Thanks! I have yet to test, but my proposed solution before your reply was to create a fifo, have sylog-ng log there and use 'cat' as root to push it to /dev/ttyS0. I will now look into AppArmor policies. -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.7 (MingW32) Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org iD8DBQFHTybUsJJnSzEQqpgRAj7hAJ9epoAeL7FEQQ29+0QTgfvZg4IBtwCeNfQg POGQStbuZAThO8hzq6jMmC4= =pefK -----END PGP SIGNATURE-----
participants (5)
-
Balazs Scheidler
-
Kjell Danielsen
-
kjell.danielsen＠hjemme.no
-
Valdis.Kletnieks＠vt.edu
-
Vidar Tyldum Hansen