Empty ppp log running snapshot of 6-Apr-2011 and "official" RC3

wallabybob

I'm running 2.0-RC1-IPv6 (i386) built on Wed Apr 6 23:30:13 EDT 2011 My WAN interface runs ppp and is up but the ppp log file is empty:

*** Welcome to pfSense 2.0-RC1-IPv6-pfSense (i386) on pfsense ***

WAN (wan) -> pppoe1 -> 203.144.5.7/32 NONE/NONE (PPPoE)
LAN (lan) -> bridge0 -> 192.168.211.173/25 2001:470:1f05:14b3::1/64
WLAN (opt1) -> ath0_wlan0 -> NONE/NONE NONE/NONE
DMZ (opt2) -> rl0_vlan15 -> 192.168.37.197/28 NONE/NONE
MODEM (opt4) -> ue0 -> NONE/NONE NONE/NONE
OPT5 (opt5) -> rl0_vlan10 -> 192.168.1.2/24 NONE/NONE
PHYSLAN (opt6) -> vr0 -> NONE/NONE NONE/NONE
WANIPV6 (opt7) -> gif0 -> NONE/NONE 2001:470:1f04:14b3::2/126

Logout (SSH only) 8) Shell

Assign Interfaces 9) pfTop

Set interface(s) IP address 10) Filter Logs

Reset webConfigurator password 11) Restart webConfigurator

Reset to factory defaults 12) pfSense Developer Shell

Reboot system 13) Upgrade from console

Halt system 14) Disable Secure Shell (sshd)

Ping host

Enter an option: 8

ifconfig pppoe1

pppoe1: flags=88d1 <up,pointopoint,running,noarp,simplex,multicast>metric 0 mtu 1492
inet 203.144.5.7 –> 121.50.212.5 netmask 0xffffffff
inet6 fe80::219:e0ff:fe68:314b%pppoe1 prefixlen 64 scopeid 0xb
nd6 options=3 <performnud,accept_rtadv># clog /var/log/ppp.log
#</performnud,accept_rtadv></up,pointopoint,running,noarp,simplex,multicast>

Since pppoe1 is up I expect there to be something in the ppp log.

wallabybob

I had non-empty PPP logs when running a snapshot built 21-May-2011.

A few hours ago I upgraded to the "official" RC3: 2.0-RC3-IPv6 (i386)
built on Tue Jun 21 17:40:54 EDT 2011

clog /var/log/system.log | grep ppp

Jun 24 01:58:32 pfsense php: : rc.newwanip: Informational is starting pppoe1.
Jun 24 01:58:32 pfsense php: : rc.newwanip: on (IP address: 203.144.19.78) (interface: wan) (real interface: pppoe1).

clog /var/log/ppp.log

ls -l /var/log

total 1924
-rw–----- 1 root wheel 65535 Jun 24 07:36 apinger.log
-rw------- 1 root wheel 65535 Jun 24 08:15 dhcpd.log
-rw-r--r-- 1 root wheel 6538 Jun 24 01:57 dmesg.boot
-rw------- 1 root wheel 512144 Jun 24 08:07 filter.log
-rw------- 1 root wheel 65535 Jun 24 01:57 ipsec.log
-rw------- 1 root wheel 50688 Jun 24 01:57 l2tps.log
-rw-r--r-- 1 root wheel 28 Jun 24 01:59 lastlog
-rw-r--r-- 1 root wheel 49 Jun 24 01:58 lighttpd.error.log
-rw------- 1 root wheel 65535 Jun 24 01:57 lighttpd.log
-rw------- 1 root wheel 65535 Jun 24 01:57 ntpd.log
-rw------- 1 root wheel 65535 Jun 24 01:57 openvpn.log
-rw------- 1 root wheel 50688 Jun 24 01:57 poes.log
-rw------- 1 root wheel 65535 Jun 24 01:57 portalauth.log
-rw------- 1 root wheel 65535 Jun 24 01:57 ppp.log
-rw------- 1 root wheel 50688 Jun 24 01:57 pptps.log
-rw------- 1 root wheel 65535 Jun 24 01:57 relayd.log
-rw------- 1 root wheel 65535 Jun 24 01:57 slbd.log
-rw------- 1 root wheel 512144 Jun 24 08:24 system.log
-rw------- 1 root wheel 388 Jun 24 01:58 userlog
-rw------- 1 root wheel 65535 Jun 24 01:57 vpn.log

# ps ax | grep ppp

7740 ?? Ss 0:01.70 /usr/local/sbin/mpd5 -b -k -d /var/etc -f mpd_wan.conf -p /var/run/pppoe_wan.pid -s ppp pppoeclien
31952 0 R+ 0:00.01 grep ppp

more /var/etc/mpd_wan.conf

startup:
# configure the console
set console close
# configure the web server
set web close

default:
pppoeclient:
create bundle static wan
set bundle enable ipv6cp
set iface name pppoe1
set iface route default
set iface disable on-demand
set iface idle 0
set iface enable tcpmssfix
set iface up-script /usr/local/sbin/ppp-linkup
set iface down-script /usr/local/sbin/ppp-linkdown
set ipcp ranges 0.0.0.0/0 0.0.0.0/0
#log -bund -ccp -chat -iface -ipcp -lcp -link

create link static wan_link0 pppoe
set link action bundle wan
set link disable multilink
set link keep-alive 10 60
set link max-redial 0
set link disable chap pap
set link accept chap pap eap
set link disable incoming
set link mtu 1492
set auth authname "*********"
set auth password ********
set pppoe iface rl0_vlan10
open

I direct syslog output to another system and it shows ppp logging just a few minutes before the firmware upgrade but none after the upgrade which was more than 7 hours ago. My WAN link is a pppoe link and I can access the Internet over the WAN link so I expected to see at least one ppp UP event in the ppp log file.

There is at least one other thread with a complaint about level of logging from mpd so I went looking for documentation which I found at http://mpd.sourceforge.net/doc5/ That documentation says mpd logs with facility name mpd but pfSense seems to have changed that to ppp.

I noticed that mpd_wan.conf (displayed above) doesn't enable any logging (there is a commented log command). I edited mpd_wan.conf to add a command log +all, disabled the WAN link and enabled it again and now there is quite a bit of logging in /var/log/ppp.log.

Has the default level of logging in mpd changed? Or has the contents of the mpd_<interface>.conf files changed? If so, why?</interface>

wallabybob

I've just looked again at /var/etc/mpd_wan.conf and my edit to add "log +all" has gone. Maybe this file is regenerated on enabling an interface rather than startup time.

Which leaves the puzzle of why there was no ppp logging. Something not correctly synchronised at startup?