Koozali.org: home of the SME Server

Logging PPTP connections in SME 7.1

aearenda

Logging PPTP connections in SME 7.1
« on: March 17, 2007, 01:58:31 AM »
My SME Server logs PPTP CHAP authentication failures but not successes. I need to know who has been connected. Previous responses to this question I have found refer to older versions of SME server, 7.1 does not appear to log the connecting user by default.

How do I enable logging of successful PPTP connections, so I know who connected, and when?

Offline pfloor

  • ****
  • 889
  • +1/-0
Logging PPTP connections in SME 7.1
« Reply #1 on: March 17, 2007, 06:58:12 AM »
Server does log every conection and disconnection like this:

CONNECTION:

Mar 16 23:39:45 spock pptpd[6083]: CTRL: Client xxx.xxx.xxx.xxx control connection started
Mar 16 23:39:45 spock pptpd[6083]: CTRL: Starting call (launching pppd, opening GRE)
Mar 16 23:39:45 spock pppd[6084]: Plugin radius.so loaded.
Mar 16 23:39:45 spock pppd[6084]: RADIUS plugin initialized.
Mar 16 23:39:46 spock pppd[6084]: pppd 2.4.4 started by root, uid 0
Mar 16 23:39:46 spock kernel: divert: not allocating divert_blk for non-ethernet device ppp1
Mar 16 23:39:46 spock pppd[6084]: Using interface ppp1
Mar 16 23:39:46 spock pppd[6084]: Connect: ppp1 <--> /dev/pts/1
Mar 16 23:39:46 spock pptpd[6083]: CTRL: Ignored a SET LINK INFO packet with real ACCMs!
Mar 16 23:39:47 spock hald[4565]: Timed out waiting for hotplug event 454. Rebasing to 455
Mar 16 23:39:49 spock pptpd[6083]: CTRL: Ignored a SET LINK INFO packet with real ACCMs!
Mar 16 23:39:49 spock kernel: PPP MPPE Compression module registered
Mar 16 23:39:49 spock pppd[6084]: MPPE 128-bit stateless compression enabled
Mar 16 23:39:51 spock pppd[6084]: found interface eth0 for proxy arp
Mar 16 23:39:51 spock pppd[6084]: local  IP address 10.0.0.1
Mar 16 23:39:51 spock pppd[6084]: remote IP address 10.0.0.250
Mar 16 23:39:51 spock esmith::event[6112]: Processing event: ip-up.pptpd ppp1 /dev/pts/1 460800 10.0.0.1 10.0.0.250 pptpd
Mar 16 23:39:51 spock esmith::event[6112]: Running event handler: /etc/e-smith/events/actions/generic_template_expand
Mar 16 23:39:51 spock esmith::event[6112]: expanding /etc/rc.d/init.d/masq  
Mar 16 23:39:51 spock esmith::event[6112]: generic_template_expand=action|Event|ip-up.pptpd|Action|generic_template_expand|Start|1174109991 484674|End|1174109991 895516|Elapsed|0.410842
Mar 16 23:39:51 spock esmith::event[6112]: Running event handler: /etc/e-smith/events/ip-up.pptpd/S70pptp-interface-access
Mar 16 23:39:52 spock /etc/e-smith/events/ip-up.pptpd/S70pptp-interface-access[6114]: /home/e-smith/db/configuration: OLD pptpd=service|TCPPort|1723|access|public|sessions|1|status|enabled
Mar 16 23:39:52 spock /etc/e-smith/events/ip-up.pptpd/S70pptp-interface-access[6114]: /home/e-smith/db/configuration: NEW pptpd=service|Interfaces|ppp1|TCPPort|1723|access|public|sessions|1|status|enabled
Mar 16 23:39:52 spock esmith::event[6112]: S70pptp-interface-access=action|Event|ip-up.pptpd|Action|S70pptp-interface-access|Start|1174109991 895795|End|1174109992 29948|Elapsed|0.134153
Mar 16 23:39:52 spock esmith::event[6112]: Running event handler: /etc/e-smith/events/actions/adjust-services
Mar 16 23:39:52 spock esmith::event[6112]: adjusting non-supervised masq (adjust)  
Mar 16 23:39:52 spock esmith::event[6112]: adjust-services=action|Event|ip-up.pptpd|Action|adjust-services|Start|1174109992 30261|End|1174109992 591533|Elapsed|0.561272

DISCONNECTION:

Mar 16 23:40:59 spock pppd[6084]: LCP terminated by peer (UM-^MQM-?^@<M-Mt^@^@^@^@)
Mar 16 23:40:59 spock pppd[6084]: Connect time 1.2 minutes.
Mar 16 23:40:59 spock pppd[6084]: Sent 17065 bytes, received 10833 bytes.
Mar 16 23:40:59 spock pptpd[6083]: CTRL: Reaping child PPP[6084]
Mar 16 23:40:59 spock pppd[6084]: Modem hangup
Mar 16 23:40:59 spock pppd[6084]: Connection terminated.
Mar 16 23:40:59 spock kernel: divert: no divert_blk to free, ppp1 not ethernet
Mar 16 23:40:59 spock esmith::event[6278]: Processing event: ip-down ppp1 /dev/pts/1 460800 10.0.0.1 10.0.0.250 pptpd
Mar 16 23:40:59 spock esmith::event[6278]: Running event handler: /etc/e-smith/events/actions/generic_template_expand
Mar 16 23:40:59 spock esmith::event[6278]: expanding /etc/rc.d/init.d/masq  
Mar 16 23:41:00 spock esmith::event[6278]: generic_template_expand=action|Event|ip-down|Action|generic_template_expand|Start|1174110059 775489|End|1174110060 93468|Elapsed|0.317979
Mar 16 23:41:00 spock esmith::event[6278]: Running event handler: /etc/e-smith/events/ip-down/S50isdn-down-notify
Mar 16 23:41:00 spock esmith::event[6278]: S50isdn-down-notify=action|Event|ip-down|Action|S50isdn-down-notify|Start|1174110060 93754|End|1174110060 203151|Elapsed|0.109397
Mar 16 23:41:00 spock esmith::event[6278]: Running event handler: /etc/e-smith/events/ip-down/S70pptp-interface-access
Mar 16 23:41:00 spock /etc/e-smith/events/ip-down/S70pptp-interface-access[6300]: /home/e-smith/db/configuration: OLD pptpd=service|Interfaces|ppp1|TCPPort|1723|access|public|sessions|1|status|enabled
Mar 16 23:41:00 spock /etc/e-smith/events/ip-down/S70pptp-interface-access[6300]: /home/e-smith/db/configuration: NEW pptpd=service|Interfaces||TCPPort|1723|access|public|sessions|1|status|enabled
Mar 16 23:41:00 spock esmith::event[6278]: S70pptp-interface-access=action|Event|ip-down|Action|S70pptp-interface-access|Start|1174110060 203464|End|1174110060 317275|Elapsed|0.113811
Mar 16 23:41:00 spock esmith::event[6278]: Running event handler: /etc/e-smith/events/actions/adjust-services
Mar 16 23:41:00 spock esmith::event[6278]: adjusting non-supervised masq (adjust)  
Mar 16 23:41:00 spock esmith::event[6278]: adjust-services=action|Event|ip-down|Action|adjust-services|Start|1174110060 317580|End|1174110060 778888|Elapsed|0.461308
Mar 16 23:41:00 spock pppd[6084]: Exit.
Mar 16 23:41:00 spock pptpd[6083]: CTRL: Client XXX.XXX.XXX.XXX control connection finished

What more do you require?
In life, you must either "Push, Pull or Get out of the way!"

Offline pfloor

  • ****
  • 889
  • +1/-0
Logging PPTP connections in SME 7.1
« Reply #2 on: March 17, 2007, 07:04:58 AM »
Previous post gives you where they conected from, you can also find out what user logged in and out:

Fri Mar 16 23:39:51 2007
   Acct-Session-Id = "45FB7F2717C400"
   User-Name = "admin"
   Acct-Status-Type = Start
   Service-Type = Framed-User
   Framed-Protocol = PPP
   Calling-Station-Id = "pptpd"
   Acct-Authentic = RADIUS
   NAS-Port-Type = Async
   Framed-IP-Address = 10.0.0.250
   NAS-IP-Address = 10.0.0.1
   NAS-Port = 1
   Acct-Delay-Time = 0
   Client-IP-Address = 127.0.0.1
   Acct-Unique-Session-Id = "a90b60be4b496645"
   Stripped-User-Name = "admin"
   Realm = "NULL"
   Timestamp = 1174109991


Fri Mar 16 23:40:59 2007
   Acct-Session-Id = "45FB7F2717C400"
   User-Name = "admin"
   Acct-Status-Type = Stop
   Service-Type = Framed-User
   Framed-Protocol = PPP
   Acct-Authentic = RADIUS
   Acct-Session-Time = 68
   Acct-Output-Octets = 17065
   Acct-Input-Octets = 10833
   Acct-Output-Packets = 46
   Acct-Input-Packets = 106
   Calling-Station-Id = "pptpd"
   NAS-Port-Type = Async
   Acct-Terminate-Cause = User-Request
   Framed-IP-Address = 10.0.0.250
   NAS-IP-Address = 10.0.0.1
   NAS-Port = 1
   Acct-Delay-Time = 0
   Client-IP-Address = 127.0.0.1
   Acct-Unique-Session-Id = "a90b60be4b496645"
   Stripped-User-Name = "admin"
   Realm = "NULL"
   Timestamp = 1174110059
In life, you must either "Push, Pull or Get out of the way!"

aearenda

Logging PPTP connections in SME 7.1
« Reply #3 on: March 17, 2007, 07:49:00 AM »
Thanks for your replies - the first post matches what I have been seeing, but contains no login username that I can find. However, your second post made me realise I was looking in the wrong spot, and based on the detail you sent, I have now found this info in the radius accounting log. I didn't know radius was involved in this, since it is only a stand-alone server, and so was only looking for logs created by ppp and pptpd.

Problem solved, thanks for your help!