■socatを使ってrsyslogに任意のログを記録する。
テストログを生成する目的は、ログの振り分けのテストか、
ログの加工を行うような正規化のテスト位しか思い浮かばない。
実際にログを出力する対象機器を起動しなくても、
対象機器が既に出力したログがあれば、socatによるTCP/UDP通信なら再現出来る。
$ lsb_release -a
No LSB modules are available.
Distributor ID: Debian
Description: Debian GNU/Linux 9.4 (stretch)
Release: 9.4
Codename: stretch
■まずは簡単なloggerコマンドを使用する。
$ logger -V
logger from util-linux 2.29.2
$ logger testmsg;sudo tail -1 /var/log/syslog
Apr 29 18:25:26 vm-stretch labunix: testmsg
■straceで追跡する。
$ sudo apt-get install -y strace
$ strace -ttT -e sendmsg logger testmsg 2>&1 | tr ',' '\n'
18:27:47.025010 sendmsg(3
{msg_name=NULL
msg_namelen=0
msg_iov=[{iov_base="<13>Apr 29 18:27:47 labunix: "
iov_len=29}
{iov_base="testmsg"
iov_len=7}]
msg_iovlen=2
msg_controllen=0
msg_flags=0}
0) = 36 <0.000025>
18:27:47.027006 +++ exited with 0 +++
$ strace -e open logger test 2>&1 | awk '/loginuid|passwd|localtime/'
open("/proc/self/loginuid", O_RDONLY) = 4
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 4
open("/etc/localtime", O_RDONLY|O_CLOEXEC) = 4
■「/proc/self/loginuid」は子プロセスにも継承されるので、
ログインしている以上、suしてもsudoでも変えることは出来ない。
$ sudo cat /proc/self/loginuid;echo
1000
$ su root -c 'cat /proc/self/loginuid';echo
パスワード:
1000
■「/proc/self/loginuid」の要件に合うように
完全にログインしなおせば変えられる。
$ cat /proc/self/loginuid;echo
1002
$ logger testmsg;su root -c 'tail -1 /var/log/syslog'
パスワード:
Apr 29 18:08:34 vm-stretch test: testmsg
■ログインしたユーザかどうかに関わらず、任意のユーザとして記録するには「-t」オプションを使用する。
$ logger -t dummyuser testmsg 2>&1;sudo tail -1 /var/log/syslog
Apr 29 18:29:34 vm-stretch dummyuser: testmsg
$ strace logger -t dummyuser testmsg 2>&1 | awk '/msg|loginuid|passwd|localtime/' | tr ',' '\n';sudo tail -1 /var/log/syslog
execve("/usr/bin/logger"
["logger"
"-t"
"dummyuser"
"testmsg"]
[/* 22 vars */]) = 0
open("/etc/localtime"
O_RDONLY|O_CLOEXEC) = 4
sendmsg(3
{msg_name=NULL
msg_namelen=0
msg_iov=[{iov_base="<13>Apr 29 18:31:17 dummyuser: "
iov_len=31}
{iov_base="testmsg"
iov_len=7}]
msg_iovlen=2
msg_controllen=0
msg_flags=0}
0) = 38
Apr 29 18:31:17 vm-stretch dummyuser: testmsg
■「/proc/self/loginuid」のUIDを使って
「/etc/passwd」からユーザ名を引いていることが分かった。
また、「-t」オプションを使用した際には
「/proc/self/loginuid」や「/etc/passwd」は呼び出されない。
$ awk -F: '/:100[02]:/{print $3,$1}' /etc/passwd
1000 labunix
1002 test
■ローカルタイムについて
JSTのゾーンファイルであり、UTCではないことが分かる。
このことからメッセージを受信した時のシステムのローカル時刻(JST)が記録されることが分かる。
$ strings /etc/localtime
TZif2
TZif2
JST-9
$ diff -a /usr/share/zoneinfo/Asia/Tokyo >/dev/null /etc/localtime ;echo $?
0
$ diff -a /usr/share/zoneinfo/UTC /etc/localtime >/dev/null;echo $?
1
■straceのどこにもホスト名は無い。
$ logger -s -t testuser testmsg;sudo tail -1 /var/log/syslog
<13>Apr 29 18:34:03 testuser: testmsg
Apr 29 18:34:03 vmx-rdebian testuser: testmsg
■「/dev/log」に直接書き込んでみると実際、送信した時刻は無視されていることが分かる。
また、新たに「uname」システムコールが呼ばれていることが分かる。
$ sudo apt-get install -y socat
$ socat -V | awk '/socat|running|TCP|UDP|UNIX/'
socat by Gerhard Rieger - see www.dest-unreach.org
socat version 1.7.3.1 on Jul 14 2017 13:52:03
running on Linux version
$ ls -l /dev/log
lrwxrwxrwx 1 root root 28 4月 29 16:32 /dev/log -> /run/systemd/journal/dev-log
$ echo '<13>Apr 29 18:34:03 testuser: testmsg' | \
strace -e sendto socat STDIN UNIX-SENDTO:/dev/log 2>&1 | tr ',' '\n'; \
sudo tail -1 /var/log/syslog
sendto(5
"<13>Apr 29 18:34:03 testuser: te"...
38
0
{sa_family=AF_UNIX
sun_path="/dev/log"}
10) = 38
+++ exited with 0 +++
Apr 29 18:48:36 vm-stretch testuser: testmsg
$ echo '<13>Apr 29 18:34:03 testuser: testmsg' | \
strace -e uname socat STDIN UNIX-SENDTO:/dev/log 2>&1;sudo tail -1 /var/log/syslog
uname({sysname="Linux", nodename="vm-stretch", ...}) = 0
+++ exited with 0 +++
Apr 29 18:50:48 vm-stretch testuser: testmsg
■rsyslog側でUDP受信を有効にすることで、
受信時ではなく、送信した時刻を反映させ、ホスト名も変更出来る。
$ dpkg -l | awk '/^ii/&&/rsyslog/{print $2,$3}'
rsyslog 8.24.0-1
$ sudo sed -i -e 's/^#\(.*imudp\)/\1/' /etc/rsyslog.conf
$ systemctl list-units --type=service | grep syslog
rsyslog.service loaded active running System Logging Service
$ sudo systemctl restart rsyslog.service
$ sudo systemctl status rsyslog.service | cat
● rsyslog.service - System Logging Service
Loaded: loaded (/lib/systemd/system/rsyslog.service; enabled; vendor preset: enabled)
Active: active (running) since Sun 2018-04-29 18:40:27 JST; 6s ago
Docs: man:rsyslogd(8)
http://www.rsyslog.com/doc/
Main PID: 7252 (rsyslogd)
Tasks: 5 (limit: 19660)
CGroup: /system.slice/rsyslog.service
└─7252 /usr/sbin/rsyslogd -n
4月 29 18:40:27 vm-stretch systemd[1]: Starting System Logging Service...
4月 29 18:40:27 vm-stretch liblogging-stdlog[7252]: [origin software="rsyslogd" swVersion="8.24.0" x-pid="7252" x-info="http://www.rsyslog.com"] start
4月 29 18:40:27 vm-stretch systemd[1]: Started System Logging Service.
$ ss -u -an | awk '/514|^State/'
State Recv-Q Send-Q Local Address:Port Peer Address:Port
UNCONN 0 0 *:514 *:*
UNCONN 0 0 :::514 :::*
$ echo '<13>Apr 29 18:34:03 dummyhost testuser: testmsg' | \
socat STDIN UDP-SENDTO:localhost:514 2>&1;sudo tail -1 /var/log/syslog
Apr 29 18:34:03 dummyhost testuser: testmsg
■rsyslog側でTCP受信を有効にすることでも、
UDP同様、受信時ではなく、送信した時刻を反映させ、ホスト名も変更出来る。
$ sudo sed -i -e 's/^#\(.*imtcp\)/\1/' /etc/rsyslog.conf
$ grep tcp /etc/rsyslog.conf
module(load="imtcp")
input(type="imtcp" port="514")
$ sudo systemctl restart rsyslog.service
$ ss -t -an | awk '/514|^State/'
State Recv-Q Send-Q Local Address:Port Peer Address:Port
LISTEN 0 25 *:514 *:*
LISTEN 0 25 :::514 :::*
$ echo '<13>Apr 29 18:34:03 dummyhost testuser: testmsg' | \
socat STDIN TCP-CONNECT:localhost:514 2>&1;sudo tail -1 /var/log/syslog
Apr 29 18:34:03 dummyhost testuser: testmsg
■例えばvSRXのログを直接書き込んでみる。
$ sudo awk '{if($6=="UI_COMMIT_PROGRESS:"){a=$0}}END{print a}' /var/log/vSRX.log
Aug 30 03:54:20 192.168.152.15 mgd[1629]: UI_COMMIT_PROGRESS: Commit operation in progress: notifying eventd(87)
$ echo 'Aug 30 03:54:20 192.168.152.15 mgd[1629]: UI_COMMIT_PROGRESS: Commit operation in progress: notifying eventd(87)' | \
socat STDIN TCP-CONNECT:localhost:514 2>&1;sudo tail -1 /var/log/syslog
Aug 30 03:54:20 192.168.152.15 mgd[1629]: UI_COMMIT_PROGRESS: Commit operation in progress: notifying eventd(87)
■上記ログが今、発生したかのように振る舞う。
$ echo $(env LANG=C date '+%b %d %H:%M:%S')' 192.168.152.15 mgd[1629]: UI_COMMIT_PROGRESS: Commit operation in progress: notifying eventd(87)' | \
socat STDIN TCP-CONNECT:localhost:514 2>&1;sudo tail -1 /var/log/syslog
Apr 29 19:23:32 192.168.152.15 mgd[1629]: UI_COMMIT_PROGRESS: Commit operation in progress: notifying eventd(87)
■loggerコマンドの入力時1025文字の制限について
TCP/UDP/UNIXソケットでは発生しないが、loggerコマンドでは入力時1025文字を超えると
前方1025文字分が破棄されてしまうので注意。
$ seq -w 1 257 | tr '\n' ' ' | wc -c
1028
$ echo $(env LANG=C date '+%b %d %H:%M:%S')' 192.168.152.15 '$(seq -w 1 257 | tr '\n' ' ') | \
socat STDIN TCP-CONNECT:localhost:514 2>&1;sudo tail -1 /var/log/syslog | wc -c
1060
$ echo $(env LANG=C date '+%b %d %H:%M:%S')' 192.168.152.15 '$(seq -w 1 257 | tr '\n' ' ') | \
socat STDIN UDP-SENDTO:localhost:514 2>&1;sudo tail -1 /var/log/syslog | wc -c
1060
$ echo "<13>"$(env LANG=C date '+%b %d %H:%M:%S')' 192.168.152.15 '$(seq -w 1 257 | tr '\n' ' ') | \
socat STDIN UNIX-SENDTO:/dev/log ;sudo tail -1 /var/log/syslog | wc -c
1071
$ echo $(seq -w 1 249 | tr '\n' ' ') | logger -s 2>&1 | wc -c ;sudo tail -1 /var/log/syslog | wc -c
1025
1032
$ echo $(seq -w 1 249 | tr '\n' ' ')0 | logger -s 2>&1 | awk '{print "echo \047"$0"\047 | wc -c"}' | sh;sudo tail -1 /var/log/syslog
1025
32
Apr 29 19:51:17 vm-stretch labunix: 0
$ for n in `seq 240 256`;do \
echo $(seq -w 1 $n | tr '\n' ' ') | logger -s 2>&1 | wc -c | xargs echo -n;echo -e "\t$n" ; \
sudo tail -1 /var/log/syslog | wc -c | xargs echo -n;echo -e "\t$n"; \
done
989 240
996 240
993 241
1000 241
997 242
1004 242
1001 243
1008 243
1005 244
1012 244
1009 245
1016 245
1013 246
1020 246
1017 247
1024 247
1021 248
1028 248
1025 249
1032 249
1059 250
41 250
1063 251
45 251
1067 252
49 252
1071 253
53 253
1075 254
57 254
1079 255
61 255
1083 256
65 256
■loggerコマンドと併用してログを調整する。
$ logger -s -p local0.alert -t dumm[111] testmsg 2>&1 | hexdump -C
00000000 3c 31 32 39 3e 41 70 72 20 32 39 20 32 30 3a 34 |<129>Apr 29 20:4|
00000010 39 3a 35 37 20 64 75 6d 6d 5b 31 31 31 5d 3a 20 |9:57 dumm[111]: |
00000020 74 65 73 74 6d 73 67 0a |testmsg.|
00000028
$ echo "<129>$(env LANG=C date '+%b %d %H:%M:%S') 192.168.152.15 dumm[111]: testmsg" | hexdump -C
00000000 3c 31 32 39 3e 41 70 72 20 32 39 20 32 30 3a 35 |<129>Apr 29 20:5|
00000010 30 3a 30 31 20 31 39 32 2e 31 36 38 2e 31 35 32 |0:01 192.168.152|
00000020 2e 31 35 20 64 75 6d 6d 5b 31 31 31 5d 3a 20 74 |.15 dumm[111]: t|
00000030 65 73 74 6d 73 67 0a |estmsg.|
00000037
■条件としてログメッセージに「testmsg」が含まれているかどうかで振り分けてみる。
$ grep -A 1 testmsg /etc/rsyslog.conf
msg, contains, "testmsg" /var/log/192.168.152.15.log
& stop
$ sudo systemctl restart rsyslog.service
$ sudo strace -tt -T -f -p `pidof rsyslogd` -e write
strace: Process 9470 attached with 10 threads
$ logger -s -p local0.alert -t dumm[111] testmsg;sudo tail -1 /var/log/192.168.152.15.log
<129>Apr 29 20:58:13 dumm[111]: testmsg
Apr 29 20:58:13 vm-stretch dumm[111]: testmsg
$ echo "<129>$(env LANG=C date '+%b %d %H:%M:%S') 192.168.152.15 dumm[111]: testmsg" | \
socat STDIN TCP-CONNECT:localhost:514 2>&1;sudo tail -1 /var/log/192.168.152.15.log
Apr 29 20:58:22 192.168.152.15 dumm[111]: testmsg
$ sudo strace -tt -T -f -p `pidof rsyslogd` -e write
strace: Process 9470 attached with 10 threads
[pid 9479] 20:58:13.005826 write(18, "Apr 29 20:58:13 vm-stretch dumm["..., 46) = 46 <0.000049>
[pid 9479] 20:58:13.017139 write(16, "Apr 29 20:58:13 vm-stretch sudo:"..., 141) = 141 <0.000171>
[pid 9479] 20:58:13.017421 write(16, "Apr 29 20:58:13 vm-stretch sudo:"..., 104) = 104 <0.000053>
[pid 9479] 20:58:13.025437 write(16, "Apr 29 20:58:13 vm-stretch sudo:"..., 86) = 86 <0.000104>
[pid 9479] 20:58:22.446241 write(18, "Apr 29 20:58:22 192.168.152.15 d"..., 50) = 50 <0.000045>
[pid 9479] 20:58:22.959734 write(16, "Apr 29 20:58:22 vm-stretch sudo:"..., 141) = 141 <0.000046>
[pid 9479] 20:58:22.960543 write(16, "Apr 29 20:58:22 vm-stretch sudo:"..., 104) = 104 <0.000026>
[pid 9479] 20:58:22.965592 write(16, "Apr 29 20:58:22 vm-stretch sudo:"..., 86) = 86 <0.000030>
■ホスト名による振り分け
そのまま送信出来ることから、逆に変換出来ない点が制限となる。
例えば、「192.168.152.15」はIPアドレスのように見えるが「/etc/hosts」を読まないホスト名として扱われる。
「hostname」で振り分けが出来、「fromhost-ip」で振り分けが出来ないことからも分かる。
「rsyslog.service」のサービス再起動が許される環境なら、「msg」の振り分け設定だけでも十分な気がする。
$ grep -B 1 -A 1 testmsg /etc/rsyslog.conf
hostname, isequal, "192.168.152.15" /var/log/192.168.152.15_2.log
msg, contains, "testmsg" /var/log/192.168.152.15.log
& stop
$ sudo systemctl restart rsyslog.service
$ echo "<129>$(env LANG=C date '+%b %d %H:%M:%S') 192.168.152.15 dumm[111]: testmsg" | \
socat STDIN TCP-CONNECT:localhost:514 2>&1; \
sudo tail -1 /var/log/192.168.152.15.log;sudo tail -1 /var/log/192.168.152.15_2.log
Apr 29 21:02:57 192.168.152.15 dumm[111]: testmsg
Apr 29 21:02:57 192.168.152.15 dumm[111]: testmsg
$ grep -B 2 -A 1 testmsg /etc/rsyslog.conf :hostname, isequal, "192.168.152.15" /var/log/192.168.152.15_2.log
& stop
msg, contains, "testmsg" /var/log/192.168.152.15.log
& stop
$ sudo systemctl restart rsyslog.service
$ echo "<129>$(env LANG=C date '+%b %d %H:%M:%S') 192.168.152.15 dumm[111]: testmsg" | \
socat STDIN TCP-CONNECT:localhost:514 2>&1; \
sudo tail -1 /var/log/192.168.152.15.log;sudo tail -1 /var/log/192.168.152.15_2.log
Apr 29 21:02:57 192.168.152.15 dumm[111]: testmsg
Apr 29 21:04:27 192.168.152.15 dumm[111]: testmsg
$ grep -B 3 -A 1 testmsg /etc/rsyslog.conf :fromhost-ip, iseqal, "192.168.152.15" /var/log/192.168.152.15_3.log
hostname, isequal, "192.168.152.15" /var/log/192.168.152.15_2.log
& stop
msg, contains, "testmsg" /var/log/192.168.152.15.log
& stop
$ sudo systemctl restart rsyslog.service
$ echo "<129>$(env LANG=C date '+%b %d %H:%M:%S') 192.168.152.15 dumm[111]: testmsg" | \
socat STDIN TCP-CONNECT:localhost:514 2>&1; \
sudo tail -1 /var/log/192.168.152.15.log;sudo tail -1 /var/log/192.168.152.15_2.log;sudo tail -1 /var/log/192.168.152.15_3.log
Apr 29 21:02:57 192.168.152.15 dumm[111]: testmsg
Apr 29 21:10:44 192.168.152.15 dumm[111]: testmsg
tail: '/var/log/192.168.152.15_3.log' を 読み込み用に開くことが出来ません: そのようなファイルやディレクトリはありません