syslog pppd and pptp usefulness of log information

syslog pppd and pptp usefulness of log information

[Jelle de Jong]

[-- Attachment #1: Type: text/plain, Size: 851 bytes --]

Hello everybody,

I occasionally study my syslogs and also use tools like logcheck and 
fail2ban to monitor my servers.

I often get output form the pppd en pptp daemons on my debian gnu/linux 
systems that provide almost no useful information to me what really 
happens.

- successful connections?
- repeating failed attempts?
- connected user?
- login names used
..and so on?

I comment out all debug stanza's in de config files of pppd and pptp, so 
it should run on its default settings regarding its logging.

I am not asking for more output, the lesser the better, but more useful 
information.

I attached some examples of the log messages I have in my syslog.

I would appreciate it if somebody can explain why am I having this 
information and how the quality vs quantity is configured?

Thanks in advance,

With kind regards,

Jelle de Jong

[-- Attachment #2: pptp-debug-logs-2010-06-29.txt --]
[-- Type: text/plain, Size: 9556 bytes --]

Jun 29 16:19:16 sammy pptpd[22449]: CTRL: Client 62.140.123.45 control connection started
Jun 29 16:19:17 sammy pptpd[22449]: CTRL: Starting call (launching pppd, opening GRE)
Jun 29 16:19:17 sammy pppd[22451]: Plugin /usr/lib/pptpd/pptpd-logwtmp.so loaded.
Jun 29 16:19:17 sammy pppd[22451]: pppd 2.4.4 started by root, uid 0
Jun 29 16:19:17 sammy pppd[22451]: Using interface ppp1
Jun 29 16:19:17 sammy pppd[22451]: Connect: ppp1 <--> /dev/pts/1
Jun 29 16:19:17 sammy pptpd[22449]: GRE: Bad checksum from pppd.
Jun 29 16:19:20 sammy pptpd[22449]: CTRL: Ignored a SET LINK INFO packet with real ACCMs!
Jun 29 16:19:20 sammy pppd[22451]: MPPE 128-bit stateless compression enabled
Jun 29 16:19:22 sammy pppd[22451]: found interface br0 for proxy arp
Jun 29 16:19:22 sammy pppd[22451]: local  IP address 10.10.210.11
Jun 29 16:19:22 sammy pppd[22451]: remote IP address 10.10.220.11
Jun 29 16:19:22 sammy named[22315]: received control channel command 'reconfig'
Jun 29 16:19:22 sammy named[22315]: loading configuration from '/etc/bind/named.conf'
Jun 29 16:19:22 sammy named[22315]: using default UDP/IPv4 port range: [1024, 65535]
Jun 29 16:19:22 sammy named[22315]: using default UDP/IPv6 port range: [1024, 65535]
Jun 29 16:19:22 sammy named[22315]: listening on IPv4 interface ppp1, 10.10.210.11#53
Jun 29 16:19:22 sammy named[22315]: reloading configuration succeeded
Jun 29 16:19:22 sammy named[22315]: any newly configured zones are now loaded
Jun 29 16:19:22 sammy postfix/master[4589]: reload configuration /etc/postfix

Jun 29 16:21:24 sammy pptpd[22449]: CTRL: Reaping child PPP[22451]
Jun 29 16:21:24 sammy pppd[22451]: Modem hangup
Jun 29 16:21:24 sammy pppd[22451]: Connect time 2.1 minutes.
Jun 29 16:21:24 sammy pppd[22451]: Sent 84611 bytes, received 128161 bytes.
Jun 29 16:21:24 sammy pppd[22451]: MPPE disabled
Jun 29 16:21:24 sammy pppd[22451]: Connection terminated.
Jun 29 16:21:24 sammy named[22315]: received control channel command 'reconfig'
Jun 29 16:21:24 sammy named[22315]: loading configuration from '/etc/bind/named.conf'
Jun 29 16:21:24 sammy named[22315]: using default UDP/IPv4 port range: [1024, 65535]
Jun 29 16:21:24 sammy named[22315]: using default UDP/IPv6 port range: [1024, 65535]
Jun 29 16:21:24 sammy named[22315]: no longer listening on 10.10.210.11#53
Jun 29 16:21:24 sammy named[22315]: reloading configuration succeeded
Jun 29 16:21:24 sammy named[22315]: any newly configured zones are now loaded
Jun 29 16:21:24 sammy postfix/master[4589]: reload configuration /etc/postfix
Jun 29 16:21:24 sammy pppd[22451]: Exit.
Jun 29 16:21:24 sammy pptpd[22449]: CTRL: Client 62.140.123.45 control connection finished

Jun 29 16:40:28 sammy pppd[19926]: LCP terminated by peer (^@^Z|0^@<M-Mt^@^@^@^@)
Jun 29 16:40:28 sammy pppd[19926]: Connect time 37.0 minutes.
Jun 29 16:40:28 sammy pppd[19926]: Sent 505449 bytes, received 83140 bytes.
Jun 29 16:40:28 sammy named[22315]: received control channel command 'reconfig'
Jun 29 16:40:28 sammy named[22315]: loading configuration from '/etc/bind/named.conf'
Jun 29 16:40:28 sammy named[22315]: using default UDP/IPv4 port range: [1024, 65535]
Jun 29 16:40:28 sammy named[22315]: using default UDP/IPv6 port range: [1024, 65535]
Jun 29 16:40:28 sammy named[22315]: no longer listening on 10.10.210.10#53
Jun 29 16:40:28 sammy named[22315]: reloading configuration succeeded
Jun 29 16:40:28 sammy named[22315]: any newly configured zones are now loaded
Jun 29 16:40:29 sammy postfix/master[4589]: reload configuration /etc/postfix
Jun 29 16:40:29 sammy pptpd[19924]: CTRL: Reaping child PPP[19926]
Jun 29 16:40:29 sammy pppd[19926]: Modem hangup
Jun 29 16:40:29 sammy pppd[19926]: Connection terminated.
Jun 29 16:40:29 sammy pppd[19926]: Exit.
Jun 29 16:40:29 sammy pptpd[19924]: CTRL: Client 86.94.12.34 control connection finished

Jun 29 17:09:16 sammy pptpd[31783]: CTRL: Client 86.94.12.34 control connection started
Jun 29 17:09:16 sammy pptpd[31783]: CTRL: Starting call (launching pppd, opening GRE)
Jun 29 17:09:16 sammy pppd[31784]: Plugin /usr/lib/pptpd/pptpd-logwtmp.so loaded.
Jun 29 17:09:16 sammy pppd[31784]: pppd 2.4.4 started by root, uid 0
Jun 29 17:09:16 sammy pppd[31784]: Using interface ppp0
Jun 29 17:09:16 sammy pppd[31784]: Connect: ppp0 <--> /dev/pts/0
Jun 29 17:09:16 sammy pptpd[31783]: GRE: Bad checksum from pppd.
Jun 29 17:09:19 sammy pptpd[31783]: CTRL: Ignored a SET LINK INFO packet with real ACCMs!
Jun 29 17:09:19 sammy pppd[31784]: MPPE 128-bit stateless compression enabled
Jun 29 17:09:21 sammy pppd[31784]: found interface br0 for proxy arp
Jun 29 17:09:21 sammy pppd[31784]: local  IP address 10.10.210.10
Jun 29 17:09:21 sammy pppd[31784]: remote IP address 10.10.220.10
Jun 29 17:09:21 sammy named[22315]: received control channel command 'reconfig'
Jun 29 17:09:21 sammy named[22315]: loading configuration from '/etc/bind/named.conf'
Jun 29 17:09:21 sammy named[22315]: using default UDP/IPv4 port range: [1024, 65535]
Jun 29 17:09:21 sammy named[22315]: using default UDP/IPv6 port range: [1024, 65535]
Jun 29 17:09:21 sammy named[22315]: listening on IPv4 interface ppp0, 10.10.210.10#53
Jun 29 17:09:21 sammy named[22315]: reloading configuration succeeded
Jun 29 17:09:21 sammy named[22315]: any newly configured zones are now loaded
Jun 29 17:09:22 sammy postfix/master[4589]: reload configuration /etc/postfix

Jun 29 17:38:21 sammy pppd[31784]: No response to 4 echo-requests
Jun 29 17:38:21 sammy pppd[31784]: Serial link appears to be disconnected.
Jun 29 17:38:21 sammy pppd[31784]: Connect time 29.0 minutes.
Jun 29 17:38:21 sammy pppd[31784]: Sent 173392 bytes, received 28680 bytes.
Jun 29 17:38:21 sammy pppd[31784]: MPPE disabled
Jun 29 17:38:21 sammy named[22315]: received control channel command 'reconfig'
Jun 29 17:38:21 sammy named[22315]: loading configuration from '/etc/bind/named.conf'
Jun 29 17:38:21 sammy named[22315]: using default UDP/IPv4 port range: [1024, 65535]
Jun 29 17:38:21 sammy named[22315]: using default UDP/IPv6 port range: [1024, 65535]
Jun 29 17:38:21 sammy named[22315]: no longer listening on 10.10.210.10#53
Jun 29 17:38:21 sammy named[22315]: reloading configuration succeeded
Jun 29 17:38:21 sammy named[22315]: any newly configured zones are now loaded
Jun 29 17:38:21 sammy postfix/master[4589]: reload configuration /etc/postfix
Jun 29 17:38:24 sammy pppd[31784]: Connection terminated.
Jun 29 17:38:24 sammy pppd[31784]: Modem hangup
Jun 29 17:38:24 sammy pppd[31784]: Exit.
Jun 29 17:38:24 sammy pptpd[31783]: GRE: read(fd=6,buffer=8058640,len=8196) from PTY failed: status = -1 error = Input/output error, usually caused by unexpected termination of pppd, check option syntax and pppd logs
Jun 29 17:38:24 sammy pptpd[31783]: CTRL: PTY read or GRE write failed (pty,gre)=(6,7)
Jun 29 17:38:24 sammy pptpd[31783]: CTRL: Reaping child PPP[31784]
Jun 29 17:38:24 sammy pptpd[31783]: CTRL: Client 86.94.12.34 control connection finished

Jun 29 18:00:18 sammy pptpd[8179]: CTRL: Client 86.94.12.34 control connection started
Jun 29 18:00:18 sammy pptpd[8179]: CTRL: Starting call (launching pppd, opening GRE)
Jun 29 18:00:18 sammy pppd[8180]: Plugin /usr/lib/pptpd/pptpd-logwtmp.so loaded.
Jun 29 18:00:18 sammy pppd[8180]: pppd 2.4.4 started by root, uid 0
Jun 29 18:00:18 sammy pppd[8180]: Using interface ppp0
Jun 29 18:00:18 sammy pppd[8180]: Connect: ppp0 <--> /dev/pts/0
Jun 29 18:00:18 sammy pptpd[8179]: GRE: Bad checksum from pppd.
Jun 29 18:00:21 sammy pptpd[8179]: CTRL: Ignored a SET LINK INFO packet with real ACCMs!
Jun 29 18:00:22 sammy pppd[8180]: MPPE 128-bit stateless compression enabled
Jun 29 18:00:23 sammy pppd[8180]: found interface br0 for proxy arp
Jun 29 18:00:23 sammy pppd[8180]: local  IP address 10.10.210.10
Jun 29 18:00:23 sammy pppd[8180]: remote IP address 10.10.220.10
Jun 29 18:00:23 sammy named[22315]: received control channel command 'reconfig'
Jun 29 18:00:23 sammy named[22315]: loading configuration from '/etc/bind/named.conf'
Jun 29 18:00:23 sammy named[22315]: using default UDP/IPv4 port range: [1024, 65535]
Jun 29 18:00:23 sammy named[22315]: using default UDP/IPv6 port range: [1024, 65535]
Jun 29 18:00:23 sammy named[22315]: listening on IPv4 interface ppp0, 10.10.210.10#53
Jun 29 18:00:23 sammy named[22315]: reloading configuration succeeded
Jun 29 18:00:23 sammy named[22315]: any newly configured zones are now loaded
Jun 29 18:00:23 sammy postfix/master[4589]: reload configuration /etc/postfix
Jun 29 18:01:44 sammy pptpd[8179]: CTRL: Reaping child PPP[8180]
Jun 29 18:01:44 sammy pppd[8180]: Modem hangup
Jun 29 18:01:44 sammy pppd[8180]: Connect time 1.4 minutes.
Jun 29 18:01:44 sammy pppd[8180]: Sent 170745 bytes, received 18753 bytes.
Jun 29 18:01:44 sammy pppd[8180]: MPPE disabled
Jun 29 18:01:44 sammy pppd[8180]: Connection terminated.
Jun 29 18:01:44 sammy named[22315]: received control channel command 'reconfig'
Jun 29 18:01:44 sammy named[22315]: loading configuration from '/etc/bind/named.conf'
Jun 29 18:01:44 sammy named[22315]: using default UDP/IPv4 port range: [1024, 65535]
Jun 29 18:01:44 sammy named[22315]: using default UDP/IPv6 port range: [1024, 65535]
Jun 29 18:01:44 sammy named[22315]: no longer listening on 10.10.210.10#53
Jun 29 18:01:44 sammy named[22315]: reloading configuration succeeded
Jun 29 18:01:44 sammy named[22315]: any newly configured zones are now loaded
Jun 29 18:01:44 sammy postfix/master[4589]: reload configuration /etc/postfix
Jun 29 18:01:44 sammy pppd[8180]: Exit.
Jun 29 18:01:44 sammy pptpd[8179]: CTRL: Client 86.94.12.34 control connection finished

Re: syslog pppd and pptp usefulness of log information

[Jelle de Jong]

On 29-06-10 22:46, Jelle de Jong wrote:
> I would appreciate it if somebody can explain why am I having this 
> information and how the quality vs quantity is configured?

Somebody that can help?

Thanks in advance,

With kind regards,

Jelle de Jong

Re: syslog pppd and pptp usefulness of log information

[James Carlson]

Jelle de Jong wrote:
> On 29-06-10 22:46, Jelle de Jong wrote:
>> I would appreciate it if somebody can explain why am I having this 
>> information and how the quality vs quantity is configured?
> 
> Somebody that can help?

I don't think you're going to find what you're seeking in terms of
configuration, because the debug messages were not quite designed to do
what you ask.  Pppd just doesn't have much in the way of user accounting
built in.  (In particular, I don't think detecting "repeating failed
attempts" is going to be possible inside pppd itself, as there's no good
place to store the history.  Even if one were created, distributed
authentication mechanisms such as RADIUS and PAM+NIS will make hash of it.)

The other issue is that the text of the debug log messages is not
necessarily documented as something that you can rely on.  It's possible
(however unlikely) that your favorite messages could change from release
to release of pppd, causing problems for any backend processing of the
system logs.  (Frankly, that's a common problem with all syslog-based
information, and not just messages from pppd.  The messages are usually
treated as a debugging interface for humans, not something that is
expected to be parsed by other programs.)

The documented things you can rely on are the script interfaces
(/etc/ppp/auth-up, /etc/ppp/ip-up, and so on).  There isn't currently a
documented way to detect authentication failure, at least as far as I know.

Of course, if you or someone else is volunteering to write accounting
interfaces for pppd, I suspect that'll be most welcome.  There's likely
a lot that could be done here.

-- 
James Carlson         42.703N 71.076W         <carlsonj@workingcode.com>