syslog-pppd

測試pppd的syslog


更新記錄

item note
20160727 第一版

目錄


busybox syslogd

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
xxx :[/etc]# syslogd -help
syslogd: invalid option -- 'h'
BusyBox v1.16.1 (2016-02-19 09:03:37 UTC) multi-call binary.

Usage: syslogd [OPTIONS]

System logging utility.
This version of syslogd ignores /etc/syslog.conf

Options:
-n Run in foreground
-O FILE Log to given file (default:/var/log/messages)
-l N Set local log level
-S Smaller logging output
-s SIZE Max size (KB) before rotate (default:200KB, 0=off)
-b N N rotated logs to keep (default:1, max=99, 0=purge)
-R HOST[:PORT] Log to IP or hostname on PORT (default PORT=514/UDP)
-L Log locally and via network (default is network only if -R)
-D Drop duplicates
-C[size(KiB)] Log to shared mem buffer (read it using logread)

測試pppd的syslog

帶起busybox syslogd

1
syslogd

帶起pppd查看log

  • pppd參數 記得加入debug,才會將訊息道到/var/log/message
1
pppd debug plugin rp-pppoe.so eth0 user 7476xxxx@hinet.net password wicpxxx persist usepeerdns defaultroute unit 2
  • /var/log/message
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
xxx :[/etc]# cat /var/log/messages                                                                                                                                           [25/1973]
Jul 27 17:10:24 gk350a syslog.info syslogd started: BusyBox v1.16.1
Jul 27 17:10:49 gk350a daemon.info pppd[2876]: Plugin rp-pppoe.so loaded.
Jul 27 17:10:49 gk350a daemon.info pppd[2876]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
Jul 27 17:10:49 gk350a daemon.notice pppd[2879]: pppd 2.4.7 started by root, uid 0
Jul 27 17:10:49 gk350a daemon.debug pppd[2879]: Send PPPOE Discovery V1T1 PADI session 0x0 length 12
Jul 27 17:10:49 gk350a daemon.debug pppd[2879]: dst ff:ff:ff:ff:ff:ff src 00:00:23:34:45:66
Jul 27 17:10:49 gk350a daemon.debug pppd[2879]: [service-name] [host-uniq 3f 0b 00 00]
Jul 27 17:10:54 gk350a daemon.debug pppd[2879]: Send PPPOE Discovery V1T1 PADI session 0x0 length 12
Jul 27 17:10:54 gk350a daemon.debug pppd[2879]: dst ff:ff:ff:ff:ff:ff src 00:00:23:34:45:66
Jul 27 17:10:54 gk350a daemon.debug pppd[2879]: [service-name] [host-uniq 3f 0b 00 00]
Jul 27 17:11:04 gk350a daemon.debug pppd[2879]: Send PPPOE Discovery V1T1 PADI session 0x0 length 12
Jul 27 17:11:04 gk350a daemon.debug pppd[2879]: dst ff:ff:ff:ff:ff:ff src 00:00:23:34:45:66
Jul 27 17:11:04 gk350a daemon.debug pppd[2879]: [service-name] [host-uniq 3f 0b 00 00]
Jul 27 17:11:04 gk350a daemon.debug pppd[2879]: Recv PPPOE Discovery V1T1 PADO session 0x0 length 44
Jul 27 17:11:04 gk350a daemon.debug pppd[2879]: dst 00:00:23:34:45:66 src 60:a4:4c:c7:03:f8
Jul 27 17:11:04 gk350a daemon.debug pppd[2879]: [relay-session-id 01 00 00 00 00 02 3b 10 24 8c] [host-uniq 3f 0b 00 00] [AC-name CHCH-BRAS-2221] [se]
Jul 27 17:11:04 gk350a daemon.debug pppd[2879]: Send PPPOE Discovery V1T1 PADR session 0x0 length 26
Jul 27 17:11:04 gk350a daemon.debug pppd[2879]: dst 60:a4:4c:c7:03:f8 src 00:00:23:34:45:66
Jul 27 17:11:04 gk350a daemon.debug pppd[2879]: [service-name] [host-uniq 3f 0b 00 00] [relay-session-id 01 00 00 00 00 02 3b 10 24 8c]
Jul 27 17:11:05 gk350a daemon.debug pppd[2879]: Recv PPPOE Discovery V1T1 PADS session 0x5 length 30
Jul 27 17:11:05 gk350a daemon.debug pppd[2879]: dst 00:00:23:34:45:66 src 60:a4:4c:c7:03:f8
Jul 27 17:11:05 gk350a daemon.debug pppd[2879]: [service-name] [host-uniq 3f 0b 00 00] [AC-name CHCH-BRAS-2221]
Jul 27 17:11:05 gk350a daemon.debug pppd[2879]: PADS: Service-Name: ''
Jul 27 17:11:05 gk350a daemon.info pppd[2879]: PPP session is 5
Jul 27 17:11:05 gk350a daemon.warn pppd[2879]: Connected to 60:a4:4c:c7:03:f8 via interface eth0
Jul 27 17:11:05 gk350a daemon.debug pppd[2879]: using channel 1
Jul 27 17:11:05 gk350a daemon.info pppd[2879]: Using interface ppp2
Jul 27 17:11:05 gk350a daemon.notice pppd[2879]: Connect: ppp2 <--> eth0
Jul 27 17:11:05 gk350a daemon.debug pppd[2879]: sent [LCP ConfReq id=0x1 <mru 1492> <magic 0xcd51133a>]
Jul 27 17:11:05 gk350a daemon.debug pppd[2879]: rcvd [LCP ConfReq id=0x56 <mru 1492> <auth pap> <magic 0x6437ad1e>]
Jul 27 17:11:05 gk350a daemon.debug pppd[2879]: sent [LCP ConfAck id=0x56 <mru 1492> <auth pap> <magic 0x6437ad1e>]
Jul 27 17:11:05 gk350a daemon.debug pppd[2879]: rcvd [LCP ConfAck id=0x1 <mru 1492> <magic 0xcd51133a>]
Jul 27 17:11:05 gk350a daemon.debug pppd[2879]: sent [LCP EchoReq id=0x0 magic=0xcd51133a]
Jul 27 17:11:05 gk350a daemon.debug pppd[2879]: sent [PAP AuthReq id=0x1 user="74767720@hinet.net" password=<hidden>]
Jul 27 17:11:05 gk350a daemon.debug pppd[2879]: rcvd [LCP EchoRep id=0x0 magic=0x6437ad1e]
Jul 27 17:11:05 gk350a daemon.debug pppd[2879]: rcvd [PAP AuthAck id=0x1 ""]
Jul 27 17:11:05 gk350a daemon.notice pppd[2879]: PAP authentication succeeded
Jul 27 17:11:05 gk350a daemon.notice pppd[2879]: peer from calling number 60:A4:4C:C7:03:F8 authorized
Jul 27 17:11:05 gk350a daemon.debug pppd[2879]: sent [IPCP ConfReq id=0x1 <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>]
Jul 27 17:11:05 gk350a daemon.debug pppd[2879]: rcvd [IPCP ConfReq id=0xfb <addr 168.95.98.254>]
Jul 27 17:11:05 gk350a daemon.debug pppd[2879]: sent [IPCP ConfAck id=0xfb <addr 168.95.98.254>]
Jul 27 17:11:05 gk350a daemon.debug pppd[2879]: rcvd [IPCP ConfNak id=0x1 <addr 1.165.93.76> <ms-dns1 168.95.1.1> <ms-dns2 168.95.192.1>]
Jul 27 17:11:05 gk350a daemon.debug pppd[2879]: sent [IPCP ConfReq id=0x2 <addr 1.165.93.76> <ms-dns1 168.95.1.1> <ms-dns2 168.95.192.1>]
Jul 27 17:11:05 gk350a daemon.debug pppd[2879]: rcvd [IPCP ConfAck id=0x2 <addr 1.165.93.76> <ms-dns1 168.95.1.1> <ms-dns2 168.95.192.1>]
Jul 27 17:11:05 gk350a daemon.notice pppd[2879]: local IP address 1.165.93.76
Jul 27 17:11:05 gk350a daemon.notice pppd[2879]: remote IP address 168.95.98.254
Jul 27 17:11:05 gk350a daemon.notice pppd[2879]: primary DNS address 168.95.1.1
Jul 27 17:11:05 gk350a daemon.notice pppd[2879]: secondary DNS address 168.95.192.1
Jul 27 17:11:05 gk350a daemon.debug pppd[2879]: Script /etc/ppp/ip-up started (pid 2901)
Jul 27 17:11:05 gk350a daemon.debug pppd[2879]: Script /etc/ppp/ip-up finished (pid 2901), status = 0x0

pppd重撥

  • 當第一次帶起pppd會送出PADI(Active Disconvery Initiation)
  • 等得一段時間未收到PAD0則判為timenout此時如何再次重撥

重撥的方式

  • pkill -USER2 -x -n pppd

  • 測試了二次(USR2), 此時未接上撥接的網路線

    • 每次送出PADI間隔5S,一共送出3次PADI(40S,45S,55S)
    • 再來等得約35S(與第一次送PADI時間差),若未得到PADO則為timeout
    • 因此設定至少35S才會合理,重新送出USR2的時間
  • 若第一階段(Discovery)未完成,未處理若何程序(ex. USR2),在30S之後pppd自行結束
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
Jul 28 07:34:56 gk350a daemon.debug pppd[14427]: Send PPPOE Discovery V1T1 PADI session 0x0 length 12
Jul 28 07:34:56 gk350a daemon.debug pppd[14427]: dst ff:ff:ff:ff:ff:ff src 00:00:23:34:45:66
Jul 28 07:34:56 gk350a daemon.debug pppd[14427]: [service-name] [host-uniq 5b 38 00 00]
Jul 28 07:35:01 gk350a daemon.debug pppd[14427]: Send PPPOE Discovery V1T1 PADI session 0x0 length 12
Jul 28 07:35:01 gk350a daemon.debug pppd[14427]: dst ff:ff:ff:ff:ff:ff src 00:00:23:34:45:66
Jul 28 07:35:01 gk350a daemon.debug pppd[14427]: [service-name] [host-uniq 5b 38 00 00]
Jul 28 07:35:11 gk350a daemon.debug pppd[14427]: Send PPPOE Discovery V1T1 PADI session 0x0 length 12
Jul 28 07:35:11 gk350a daemon.debug pppd[14427]: dst ff:ff:ff:ff:ff:ff src 00:00:23:34:45:66
Jul 28 07:35:11 gk350a daemon.debug pppd[14427]: [service-name] [host-uniq 5b 38 00 00]
Jul 28 07:35:31 gk350a daemon.warn pppd[14427]: Timeout waiting for PADO packets
Jul 28 07:35:31 gk350a daemon.err pppd[14427]: Unable to complete PPPoE Discovery
Jul 28 07:36:01 gk350a daemon.debug pppd[14427]: Send PPPOE Discovery V1T1 PADI session 0x0 length 12
Jul 28 07:36:01 gk350a daemon.debug pppd[14427]: dst ff:ff:ff:ff:ff:ff src 00:00:23:34:45:66
Jul 28 07:36:01 gk350a daemon.debug pppd[14427]: [service-name] [host-uniq 5b 38 00 00]
Jul 28 07:36:06 gk350a daemon.debug pppd[14427]: Send PPPOE Discovery V1T1 PADI session 0x0 length 12
Jul 28 07:36:06 gk350a daemon.debug pppd[14427]: dst ff:ff:ff:ff:ff:ff src 00:00:23:34:45:66
Jul 28 07:36:06 gk350a daemon.debug pppd[14427]: [service-name] [host-uniq 5b 38 00 00]
Jul 28 07:36:16 gk350a daemon.debug pppd[14427]: Send PPPOE Discovery V1T1 PADI session 0x0 length 12
Jul 28 07:36:16 gk350a daemon.debug pppd[14427]: dst ff:ff:ff:ff:ff:ff src 00:00:23:34:45:66
Jul 28 07:36:16 gk350a daemon.debug pppd[14427]: [service-name] [host-uniq 5b 38 00 00]
Jul 28 07:36:36 gk350a daemon.warn pppd[14427]: Timeout waiting for PADO packets
Jul 28 07:36:36 gk350a daemon.err pppd[14427]: Unable to complete PPPoE Discovery
Jul 28 07:36:36 gk350a daemon.info pppd[14427]: Exit.

Note

Some limited degree of control can be exercised over a running pppd process by sending it a signal from the list below.

  • SIGUSR1

    • This signal toggles the state of the debug option.
    • pppd預設debug訊息不會打到syslog (但其它會如: warn,err等)
    • 因此需要使用USR1來開啟debug訊息
    • Debugging can also be enabled or disabled by sending a SIGUSR1 signal to the pppd process. This signal acts as a toggle.
    • 表示:第一次使用USR1,則開啟pppd debug模式,第二次使用USER1則關閉debug模式
  • SIGUSR2

    • This signal causes pppd to renegotiate compression.
    • This can be useful to re-enable compression after it has been disabled as a result of a fatal decompression error
    • 當未收到PADO即產生timeout則此時不會自動重撥,需要使用USR2來啟動重新送出PADI訊息
  • SIGINT, SIGTERM

    • These signals cause pppd to terminate the link (by closing LCP), restore the serial device settings, and exit.
    • 產生/etc/ppp/ip.down及相關流程,並且結束pppd
  • SIGHUP

    • This signal causes pppd to terminate the link, restore the serial device settings, and close the serial device
    • If the persist or demand option has been specified, pppd will try to reopen the serial device and start another connection (after the holdoff period)
    • 當有persist參數時,產生/etc/ppp/ip.down及相關流程,之後再重新撥號,此時ppppd尚未關閉(若成功撥號成功)
    • 可用來當gateway pin不到時,重新撥接 (關閉ppp2介面,再重新撥接)

pppd撥接成功

  • defaultroute
    • Add a default route to the system routing tables, using the peer as the gateway, when IPCP negotiation is successfully completed
  • usepeerdns

    • Ask the peer for up to 2 DNS server addresses.
    • 更新/etc/pppp/resolv.conf
  • 先執行/etc/ppp/ip-up

  • 之後再執行 :

  • /etc/ppp/ip-up.d/0000usepeerdns

    • 有設定此參數usepeerdns,才會執行此0000usepeerdns,使用撥接的dns
  • /etc/ppp/ip-up.d/000resolvconf

    • 不在存/sbin/resolvconf ,內容不會執行
    • resolvconf: manage nameserver information
  • /etc/ppp/ip-up.d/0dns-up

    • 不存在/usr/sbin/pppconfig,內容不會執行
    • pppconfig:configure pppd to connect to the Internet
  • /etc/ppp/ip-up.d/ez-ipupdate

    • 不存在/usr/sbin/ez-ipupdate,內容不會執行
    • ez-ipupdate: 用來更新ddns
  • pppoe up syslog message
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
Jul 28 08:27:28 gk350a daemon.info pppd[1362]: Plugin rp-pppoe.so loaded.
Jul 28 08:27:28 gk350a daemon.info pppd[1362]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
Jul 28 08:27:28 gk350a daemon.notice pppd[1365]: pppd 2.4.7 started by root, uid 0
Jul 28 08:28:03 gk350a daemon.warn pppd[1365]: Timeout waiting for PADO packets
Jul 28 08:28:03 gk350a daemon.err pppd[1365]: Unable to complete PPPoE Discovery
Jul 28 08:28:33 gk350a daemon.info pppd[1365]: PPP session is 5
Jul 28 08:28:33 gk350a daemon.warn pppd[1365]: Connected to 60:a4:4c:c7:03:f8 via interface eth0
Jul 28 08:28:33 gk350a daemon.info pppd[1365]: Using interface ppp2
Jul 28 08:28:33 gk350a daemon.notice pppd[1365]: Connect: ppp2 <--> eth0
Jul 28 08:28:34 gk350a daemon.notice pppd[1365]: PAP authentication succeeded
Jul 28 08:28:34 gk350a daemon.notice pppd[1365]: peer from calling number 60:A4:4C:C7:03:F8 authorized
Jul 28 08:28:34 gk350a daemon.notice pppd[1365]: local IP address 1.165.87.189
Jul 28 08:28:34 gk350a daemon.notice pppd[1365]: remote IP address 168.95.98.254
Jul 28 08:28:34 gk350a daemon.notice pppd[1365]: primary DNS address 168.95.1.1
Jul 28 08:28:34 gk350a daemon.notice pppd[1365]: secondary DNS address 168.95.192.1

pppd關閉

  • pppoe down syslog message
1
2
3
4
5
Jul 28 09:15:54 gk350a daemon.info pppd[1365]: Terminating on signal 15
Jul 28 09:15:54 gk350a daemon.info pppd[1365]: Connect time 14.8 minutes.
Jul 28 09:15:54 gk350a daemon.info pppd[1365]: Sent 35638 bytes, received 40705 bytes.
Jul 28 09:15:54 gk350a daemon.notice pppd[1365]: Connection terminated.
Jul 28 09:15:56 gk350a daemon.info pppd[1365]: Exit.
  • pppoe down script程序
1
2
3
4
5
6
7
8
9
10
gk350a :[/tmp]# cat /tmp/ppp-log 
/etc/ppp/ip-up, ppp2 eth0 0 1.165.87.189 168.95.98.254
/etc/ppp/ip-up.d/0000usepeerdns, ppp2 eth0 0 1.165.87.189 168.95.98.254
/etc/ppp/ip-up.d/000resolvconf, ppp2 eth0 0 1.165.87.189 168.95.98.254
/etc/ppp/ip-up.d/0dns-up, ppp2 eth0 0 1.165.87.189 168.95.98.254
/etc/ppp/ip-up.d/ez-ipupdate, ppp2 eth0 0 1.165.87.189 168.95.98.254
/etc/ppp/ip-down, ppp2 eth0 0 1.165.87.189 168.95.98.254
/etc/ppp/ip-down.d/0000usepeerdns, ppp2 eth0 0 1.165.87.189 168.95.98.254
/etc/ppp/ip-down.d/000resolvconf, ppp2 eth0 0 1.165.87.189 168.95.98.254
/etc/ppp/ip-down.d/0dns-down, ppp2 eth0 0 1.165.87.189 168.95.98.254

/etc/pppd 目錄結構

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
gk350a :[/tmp]# ls -l /etc/ppp
-rwxr-xr-x 1 1000 1000 109 Feb 16 03:57 chap-secrets
-rwxr-xr-x 1 1000 1000 1785 Jul 28 08:18 ip-down
drwxr-xr-x 2 1000 1000 4096 Jul 28 08:21 ip-down.d
-rwxr-xr-x 1 1000 1000 1923 Jul 28 08:18 ip-up
drwxr-xr-x 2 1000 1000 4096 Jul 28 08:20 ip-up.d
-rwxr-xr-x 1 1000 1000 815 Jul 28 08:22 ipv6-down
-rwxr-xr-x 1 1000 1000 952 Jul 28 08:23 ipv6-up
-rwxr-xr-x 1 1000 1000 13487 Feb 16 03:57 options
-rwxr-xr-x 1 1000 1000 1665 Feb 16 03:57 pap-secrets
drwxr-xr-x 2 1000 1000 4096 Jul 28 08:23 plugins
-rwxr-xr-x 1 1000 1000 123 Feb 16 03:57 pppoe-server-options
-rwxr-xr-x 1 1000 1000 4524 Feb 16 03:57 pppoe.conf
lrwxrwxrwx 1 root root 25 Jul 27 10:11 resolv.conf -> ../../tmp/ppp-resolv.conf

gk350a :[/tmp]# ls -l /etc/ppp/ip-up.d
-rwxr-xr-x 1 1000 1000 933 Jul 28 08:18 0000usepeerdns
-rwxr-xr-x 1 1000 1000 546 Jul 28 08:19 000resolvconf
-rwxr-xr-x 1 1000 1000 4056 Jul 28 08:19 0dns-up
-rwxr-xr-x 1 1000 1000 727 Jul 28 08:20 ez-ipupdate

gk350a :[/tmp]# cat /tmp/ppp-log
/etc/ppp/ip-up, ppp2 eth0 0 1.165.87.189 168.95.98.254
/etc/ppp/ip-up.d/0000usepeerdns, ppp2 eth0 0 1.165.87.189 168.95.98.254
/etc/ppp/ip-up.d/000resolvconf, ppp2 eth0 0 1.165.87.189 168.95.98.254
/etc/ppp/ip-up.d/0dns-up, ppp2 eth0 0 1.165.87.189 168.95.98.254
/etc/ppp/ip-up.d/ez-ipupdate, ppp2 eth0 0 1.165.87.189 168.95.98.254

參考來源