labunix's blog

labunixのラボUnix

socatを使ってrsyslogに任意のログを記録する。

■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 #1 SMP Debian 4.9.30-2+deb9u5 (2017-09-19), release 4.9.0-3-amd64, machine x86_64
  #define WITH_UNIX 1
  #define WITH_ABSTRACT_UNIXSOCKET 1
  #define WITH_TCP 1
  #define WITH_UDP 1

$ ls -l /dev/log 
lrwxrwxrwx 1 root root 28  429 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

 429 18:40:27 vm-stretch systemd[1]: Starting System Logging Service...
 429 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
 429 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' を 読み込み用に開くことが出来ません: そのようなファイルやディレクトリはありません