Syslog remote logging problem after reboot



  • Anyone else having problems with remote syslogging after a reboot? My installation does not send any syslogs until I manually restart syslogd.
    I have tried to debug this, /var/etc/syslog.conf looks OK after a reboot, my . @192.168.1.100 is there. It's running OK with
    /usr/sbin/syslogd -s -c -c -l /var/dhcpd/var/run/log -f /var/etc/syslog.conf
    but it's not sending anything to my loghost.
    I ran tcpdump -nvvi <interface>port 514 on each of my interfaces/VLANs and also on lo0. Then I logged in via SSH which normally triggers a syslog entry to be sent. No traffic leaving the box though. Manually killing the PID and starting syslog again with the above parameters helps, it logs to my remote host instantly.
    Any idea?
    I am currently on
    2.1-BETA1 (i386)
    built on Tue Jan 29 16:42:56 EST 2013
    FreeBSD 8.3-RELEASE-p5</interface>



  • I'm running "2.1-BETA1 (i386) built on Wed Jan 30 04:20:11 EST 2013" after reboot upgrading
    to that version from previous snap and remote syslogging is working as expected. No problem there.
    Tested the ssh login and in came up OK in the syslog-server fine.

    //Dan Lundqvist, SWEDEN



  • I also tried a reset to factory defaults now. After that I just disabled IPv6 on the LAN/WAN interface, set a DNS and went straight to the remote syslog settings, remote logging works. After a reboot it stops working. The first message in /var/log/system.log is:

    syslogd: sendto: Network is unreachable
    

    I'm getting this error on all my pfSense hosts: An ALIX board, a KVM and an old Dell Notebook.
    The config says:

    	 <syslog><nentries>50</nentries>
    		<remoteserver>192.168.1.100</remoteserver>
    		 <remoteserver2><remoteserver3><logall><enable></enable></logall></remoteserver3></remoteserver2></syslog> 
    

    What am I doing wrong?



  • I am NOT seeing any "syslogd: sendto: Network is unreachable" in my system.log.
    And it works fine even after reboot.

    And my config looks like this:

    	 <syslog><nentries>50</nentries>
    		<remoteserver>192.168.120.62</remoteserver>
    		 <remoteserver2><remoteserver3><enable><logall></logall></enable></remoteserver3></remoteserver2></syslog> 
    

    //Dan


  • Rebel Alliance Developer Netgate

    Where is 192.168.120.62? On your LAN? Across a VPN? Somewhere else? If it's local, what type of interface is it on? Captive portal enabled there?

    I've got a router on 2.1 just installed on Friday that does remote syslog across OpenVPN and it works fine after a reboot, no problems there at all.



  • My devices are all in the same LAN subnet, even on the same switch. I played a little with an ALIX Board, no VLANs, just plain vr interfaces. LAN static, WAN DHCP. No captive portal, just the freeradius2 package installed, OpenVPN and IPsec VPN enabled.
    Strangely logging works when I use my local IPv6 net. As that does not rely on ARP, I had a look at my switch configuration (Cisco SG300), but playing with ARP and MAC age settings did not help. Then I tried the hardware settings on the ALIX, but after enabling Device Polling it became unreachable after reboot. I have power cycle it tonight, I was doing the tests remote.
    Is it normal for dmesg printing those after reboot? I always get those…

    Trying to mount root from ufs:/dev/ufs/pfsense1
    vr1: link state changed to DOWN
    vr1: link state changed to UP
    vr0: link state changed to DOWN
    pflog0: promiscuous mode enabled
    vr0: link state changed to UP
    


  • @jimp:

    Where is 192.168.120.62? On your LAN? Across a VPN? Somewhere else? If it's local, what type of interface is it on? Captive portal enabled there?

    I've got a router on 2.1 just installed on Friday that does remote syslog across OpenVPN and it works fine after a reboot, no problems there at all.

    Jimp: My system is working OK and the 192.168.120.62 is on the local LAN subnet and normal NIC interface. And not using captive portal.
    It is "athurdent" who has problems.  Just briefing him that it is not generic problem with 2.1 but seems to be a local problem.

    The reason to why I included my config was just to show him how my working one looks like.  :)

    //Dan



  • @athurdent:

    Strangely logging works when I use my local IPv6 net.

    There is a fix that restarts syslog at the end of the booting process when an IPv6 address is being used. The reason for that fix was very similar to the problem you are experiencing, where syslog would not send logs over IPv6 at bootup. Here is that note http://redmine.pfsense.org/issues/2370#note-12.



  • Thanks, I think I'll stick with IPv6 for now. I know it used to work after a reboot, I am using and updating my pfSense 2.1 KVM for approx. a year now. If I changed something relevant to that in my network, I cannot find it. As it works everywhere else, I'll keep on looking and report back when I find the cause. Thanks for the help so far!



  • I have the same problem with my test server (built on Mon Feb 4 03:44:55 EST 2013), no entries in remote syslog.

    
    	 <syslog><reverse><nentries>50</nentries>
    		 <logall><nologdefaultblock><remoteserver>192.168.10.10</remoteserver>
    		 <remoteserver2><remoteserver3><enable></enable></remoteserver3></remoteserver2></nologdefaultblock></logall></reverse></syslog> 
    
    

    Remote syslog server is in same LAN.

    My "production" pfSense machine (built on Mon Jan 28 07:27:34 EST 2013 [not updated, before new Status Queues page works]) does send  events to remote syslog.

    
    	 <syslog><nentries>100</nentries>
    		 <reverse><remoteserver>192.168.10.10</remoteserver>
    		 <remoteserver2><remoteserver3><enable><nologdefaultblock><dhcp><portalauth><vpn><apinger><relayd><hostapd></hostapd></relayd></apinger></vpn></portalauth></dhcp></nologdefaultblock></enable></remoteserver3></remoteserver2></reverse></syslog> 
    
    


  • Interesting, what is the first entry in /var/log/system.log?



  • @athurdent:

    Interesting, what is the first entry in /var/log/system.log?

    Feb 5 11:25:06	kernel: Copyright (c) 1992-2012 The FreeBSD Project.
    

    And because I don't think that that is enough, so here's a bit more:

    
    Feb 5 11:25:06	kernel: Copyright (c) 1992-2012 The FreeBSD Project.
    Feb 5 11:25:06	kernel: Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
    Feb 5 11:25:06	kernel: The Regents of the University of California. All rights reserved.
    Feb 5 11:25:06	kernel: FreeBSD is a registered trademark of The FreeBSD Foundation.
    Feb 5 11:25:06	kernel: FreeBSD 8.3-RELEASE-p5 #1: Mon Feb 4 04:12:41 EST 2013
    Feb 5 11:25:06	kernel: root@snapshots-8_3-i386.builders.pfsense.org:/usr/obj./usr/pfSensesrc/src/sys/pfSense_SMP.8 i386
    Feb 5 11:25:06	kernel: Timecounter "i8254" frequency 1193182 Hz quality 0
    Feb 5 11:25:06	kernel: CPU: Intel(R) Core(TM)2 Duo CPU T7700 @ 2.40GHz (2488.27-MHz 686-class CPU)
    Feb 5 11:25:06	kernel: Origin = "GenuineIntel" Id = 0x6fa Family = 6 Model = f Stepping = 10
    Feb 5 11:25:06	kernel: Features=0xfa3fbff <fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,pse36,dts,mmx,fxsr,sse,sse2,ss>Feb 5 11:25:06	kernel: Features2=0x80202201 <sse3,ssse3,cx16,x2apic,hv>Feb 5 11:25:06	kernel: AMD Features=0x20100000 <nx,lm>Feb 5 11:25:06	kernel: AMD Features2=0x1 <lahf>Feb 5 11:25:06	kernel: TSC: P-state invariant
    Feb 5 11:25:06	kernel: real memory = 268435456 (256 MB)
    Feb 5 11:25:06	kernel: avail memory = 238817280 (227 MB)
    Feb 5 11:25:06	kernel: ACPI APIC Table: <ptltd apic="">Feb 5 11:25:06	kernel: MADT: Forcing active-low polarity and level trigger for SCI
    Feb 5 11:25:06	kernel: ioapic0 <version 1.1="">irqs 0-23 on motherboard
    Feb 5 11:25:06	kernel: wlan: mac acl policy registered
    Feb 5 11:25:06	kernel: ipw_bss: You need to read the LICENSE file in /usr/share/doc/legal/intel_ipw/.
    Feb 5 11:25:06	kernel: ipw_bss: If you agree with the license, set legal.intel_ipw.license_ack=1 in /boot/loader.conf.
    Feb 5 11:25:06	kernel: module_register_init: MOD_LOAD (ipw_bss_fw, 0xc07b9a10, 0) error 1
    Feb 5 11:25:06	kernel: ipw_ibss: You need to read the LICENSE file in /usr/share/doc/legal/intel_ipw/.
    Feb 5 11:25:06	kernel: ipw_ibss: If you agree with the license, set legal.intel_ipw.license_ack=1 in /boot/loader.conf.
    Feb 5 11:25:06	kernel: module_register_init: MOD_LOAD (ipw_ibss_fw, 0xc07b9ab0, 0) error 1
    Feb 5 11:25:06	kernel: ipw_monitor: You need to read the LICENSE file in /usr/share/doc/legal/intel_ipw/.
    Feb 5 11:25:06	kernel: ipw_monitor: If you agree with the license, set legal.intel_ipw.license_ack=1 in /boot/loader.conf.
    Feb 5 11:25:06	kernel: module_register_init: MOD_LOAD (ipw_monitor_fw, 0xc07b9b50, 0) error 1
    Feb 5 11:25:06	kernel: kbd1 at kbdmux0
    Feb 5 11:25:06	kernel: cryptosoft0: <software crypto="">on motherboard
    Feb 5 11:25:06	kernel: padlock0: No ACE support.
    Feb 5 11:25:06	kernel: acpi0: <intel 440bx="">on motherboard
    Feb 5 11:25:06	kernel: acpi0: [ITHREAD]
    Feb 5 11:25:06	kernel: acpi0: Power Button (fixed)
    Feb 5 11:25:06	kernel: Timecounter "HPET" frequency 14318180 Hz quality 900
    Feb 5 11:25:06	kernel: Timecounter "ACPI-fast" frequency 3579545 Hz quality 1000
    Feb 5 11:25:06	kernel: acpi_timer0: <24-bit timer at 3.579545MHz> port 0x1008-0x100b on acpi0
    Feb 5 11:25:06	kernel: cpu0: <acpi cpu="">on acpi0
    Feb 5 11:25:06	kernel: pcib0: <acpi host-pci="" bridge="">port 0xcf8-0xcff on acpi0
    Feb 5 11:25:06	kernel: pci0: <acpi pci="" bus="">on pcib0
    Feb 5 11:25:06	kernel: pcib1: <acpi pci-pci="" bridge="">at device 1.0 on pci0
    Feb 5 11:25:06	kernel: pci1: <acpi pci="" bus="">on pcib1
    Feb 5 11:25:06	kernel: isab0: <pci-isa bridge="">at device 7.0 on pci0
    Feb 5 11:25:06	kernel: isa0: <isa bus="">on isab0
    Feb 5 11:25:06	kernel: atapci0: <intel piix4="" udma33="" controller="">port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0x10c0-0x10cf at device 7.1 on pci0
    Feb 5 11:25:06	kernel: ata0: <ata channel="">at channel 0 on atapci0
    Feb 5 11:25:06	kernel: ata0: [ITHREAD]
    Feb 5 11:25:06	kernel: ata1: <ata channel="">at channel 1 on atapci0
    Feb 5 11:25:06	kernel: ata1: [ITHREAD]
    Feb 5 11:25:06	kernel: pci0: <bridge>at device 7.3 (no driver attached)
    Feb 5 11:25:06	kernel: pci0: <base peripheral=""> at device 7.7 (no driver attached)
    Feb 5 11:25:06	kernel: vgapci0: <vga-compatible display="">port 0x10d0-0x10df mem 0xd0000000-0xd7ffffff,0xc8800000-0xc8ffffff irq 16 at device 15.0 on pci0
    Feb 5 11:25:06	kernel: pcib2: <acpi pci-pci="" bridge="">at device 17.0 on pci0
    Feb 5 11:25:06	kernel: pci2: <acpi pci="" bus="">on pcib2
    Feb 5 11:25:06	kernel: em0: <intel(r) 1000="" pro="" legacy="" network="" connection="" 1.0.4="">port 0x2000-0x203f mem 0xc9020000-0xc903ffff,0xc9000000-0xc900ffff irq 18 at device 0.0 on pci2
    Feb 5 11:25:06	kernel: em0: Memory Access and/or Bus Master bits were not set!
    Feb 5 11:25:06	kernel: em0: [FILTER]
    Feb 5 11:25:06	kernel: em1: <intel(r) 1000="" pro="" legacy="" network="" connection="" 1.0.4="">port 0x2040-0x207f mem 0xc9040000-0xc905ffff,0xc9010000-0xc901ffff irq 19 at device 1.0 on pci2
    Feb 5 11:25:06	kernel: em1: Memory Access and/or Bus Master bits were not set!
    Feb 5 11:25:06	kernel: em1: [FILTER]
    Feb 5 11:25:06	kernel: pcib3: <acpi pci-pci="" bridge="">at device 21.0 on pci0
    Feb 5 11:25:06	kernel: pci3: <acpi pci="" bus="">on pcib3
    Feb 5 11:25:06	kernel: pcib4: <acpi pci-pci="" bridge="">at device 21.1 on pci0
    Feb 5 11:25:06	kernel: pci4: <acpi pci="" bus="">on pcib4
    Feb 5 11:25:06	kernel: pcib5: <acpi pci-pci="" bridge="">at device 21.2 on pci0
    Feb 5 11:25:06	kernel: pci5: <acpi pci="" bus="">on pcib5
    Feb 5 11:25:06	kernel: pcib6: <acpi pci-pci="" bridge="">at device 21.3 on pci0
    Feb 5 11:25:06	kernel: pci6: <acpi pci="" bus="">on pcib6
    Feb 5 11:25:06	kernel: pcib7: <acpi pci-pci="" bridge="">at device 21.4 on pci0
    Feb 5 11:25:06	kernel: pci7: <acpi pci="" bus="">on pcib7
    Feb 5 11:25:06	kernel: pcib8: <acpi pci-pci="" bridge="">at device 21.5 on pci0
    Feb 5 11:25:06	kernel: pci8: <acpi pci="" bus="">on pcib8
    Feb 5 11:25:06	kernel: pcib9: <acpi pci-pci="" bridge="">at device 21.6 on pci0
    Feb 5 11:25:06	kernel: pci9: <acpi pci="" bus="">on pcib9
    Feb 5 11:25:06	kernel: pcib10: <acpi pci-pci="" bridge="">at device 21.7 on pci0
    Feb 5 11:25:06	kernel: pci10: <acpi pci="" bus="">on pcib10
    Feb 5 11:25:06	kernel: pcib11: <acpi pci-pci="" bridge="">at device 22.0 on pci0
    Feb 5 11:25:06	kernel: pci11: <acpi pci="" bus="">on pcib11
    Feb 5 11:25:06	kernel: pcib12: <acpi pci-pci="" bridge="">at device 22.1 on pci0
    Feb 5 11:25:06	kernel: pci12: <acpi pci="" bus="">on pcib12
    Feb 5 11:25:06	kernel: pcib13: <acpi pci-pci="" bridge="">at device 22.2 on pci0
    Feb 5 11:25:06	kernel: pci13: <acpi pci="" bus="">on pcib13
    Feb 5 11:25:06	kernel: pcib14: <acpi pci-pci="" bridge="">at device 22.3 on pci0
    Feb 5 11:25:06	kernel: pci14: <acpi pci="" bus="">on pcib14
    Feb 5 11:25:06	kernel: pcib15: <acpi pci-pci="" bridge="">at device 22.4 on pci0
    Feb 5 11:25:06	kernel: pci15: <acpi pci="" bus="">on pcib15
    Feb 5 11:25:06	kernel: pcib16: <acpi pci-pci="" bridge="">at device 22.5 on pci0
    Feb 5 11:25:06	kernel: pci16: <acpi pci="" bus="">on pcib16
    Feb 5 11:25:06	kernel: pcib17: <acpi pci-pci="" bridge="">at device 22.6 on pci0
    Feb 5 11:25:06	kernel: pci17: <acpi pci="" bus="">on pcib17
    Feb 5 11:25:06	kernel: pcib18: <acpi pci-pci="" bridge="">at device 22.7 on pci0
    Feb 5 11:25:06	kernel: pci18: <acpi pci="" bus="">on pcib18
    Feb 5 11:25:06	kernel: pcib19: <acpi pci-pci="" bridge="">at device 23.0 on pci0
    Feb 5 11:25:06	kernel: pci19: <acpi pci="" bus="">on pcib19
    Feb 5 11:25:06	kernel: pcib20: <acpi pci-pci="" bridge="">at device 23.1 on pci0
    Feb 5 11:25:06	kernel: pci20: <acpi pci="" bus="">on pcib20
    Feb 5 11:25:06	kernel: pcib21: <acpi pci-pci="" bridge="">at device 23.2 on pci0
    Feb 5 11:25:06	kernel: pci21: <acpi pci="" bus="">on pcib21
    Feb 5 11:25:06	kernel: pcib22: <acpi pci-pci="" bridge="">at device 23.3 on pci0
    Feb 5 11:25:06	kernel: pci22: <acpi pci="" bus="">on pcib22
    Feb 5 11:25:06	kernel: pcib23: <acpi pci-pci="" bridge="">at device 23.4 on pci0
    Feb 5 11:25:06	kernel: pci23: <acpi pci="" bus="">on pcib23
    Feb 5 11:25:06	kernel: pcib24: <acpi pci-pci="" bridge="">at device 23.5 on pci0
    Feb 5 11:25:06	kernel: pci24: <acpi pci="" bus="">on pcib24
    Feb 5 11:25:06	kernel: pcib25: <acpi pci-pci="" bridge="">at device 23.6 on pci0
    Feb 5 11:25:06	kernel: pci25: <acpi pci="" bus="">on pcib25
    Feb 5 11:25:06	kernel: pcib26: <acpi pci-pci="" bridge="">at device 23.7 on pci0
    Feb 5 11:25:06	kernel: pci26: <acpi pci="" bus="">on pcib26
    Feb 5 11:25:06	kernel: pcib27: <acpi pci-pci="" bridge="">at device 24.0 on pci0
    Feb 5 11:25:06	kernel: pci27: <acpi pci="" bus="">on pcib27
    Feb 5 11:25:06	kernel: pcib28: <acpi pci-pci="" bridge="">at device 24.1 on pci0
    Feb 5 11:25:06	kernel: pci28: <acpi pci="" bus="">on pcib28
    Feb 5 11:25:06	kernel: pcib29: <acpi pci-pci="" bridge="">at device 24.2 on pci0
    Feb 5 11:25:06	kernel: pci29: <acpi pci="" bus="">on pcib29
    Feb 5 11:25:06	kernel: pcib30: <acpi pci-pci="" bridge="">at device 24.3 on pci0
    Feb 5 11:25:06	kernel: pci30: <acpi pci="" bus="">on pcib30
    Feb 5 11:25:06	kernel: pcib31: <acpi pci-pci="" bridge="">at device 24.4 on pci0
    Feb 5 11:25:06	kernel: pci31: <acpi pci="" bus="">on pcib31
    Feb 5 11:25:06	kernel: pcib32: <acpi pci-pci="" bridge="">at device 24.5 on pci0
    Feb 5 11:25:06	kernel: pci32: <acpi pci="" bus="">on pcib32
    Feb 5 11:25:06	kernel: pcib33: <acpi pci-pci="" bridge="">at device 24.6 on pci0
    Feb 5 11:25:06	kernel: pci33: <acpi pci="" bus="">on pcib33
    Feb 5 11:25:06	kernel: pcib34: <acpi pci-pci="" bridge="">at device 24.7 on pci0
    Feb 5 11:25:06	kernel: pci34: <acpi pci="" bus="">on pcib34
    Feb 5 11:25:06	kernel: acpi_acad0: <ac adapter="">on acpi0
    Feb 5 11:25:06	kernel: atrtc0: <at realtime="" clock="">port 0x70-0x71 irq 8 on acpi0
    Feb 5 11:25:06	kernel: atkbdc0: <keyboard controller="" (i8042)="">port 0x60,0x64 irq 1 on acpi0
    Feb 5 11:25:06	kernel: atkbd0: <at keyboard="">irq 1 on atkbdc0
    Feb 5 11:25:06	kernel: kbd0 at atkbd0
    Feb 5 11:25:06	kernel: atkbd0: [GIANT-LOCKED]
    Feb 5 11:25:06	kernel: atkbd0: [ITHREAD]
    Feb 5 11:25:06	kernel: psm0: <ps 2="" mouse="">irq 12 on atkbdc0
    Feb 5 11:25:06	kernel: psm0: [GIANT-LOCKED]
    Feb 5 11:25:06	kernel: psm0: [ITHREAD]
    Feb 5 11:25:06	kernel: psm0: model IntelliMouse, device ID 3
    Feb 5 11:25:06	kernel: ppc0: <parallel port="">port 0x378-0x37f irq 7 on acpi0
    Feb 5 11:25:06	kernel: ppc0: Generic chipset (NIBBLE-only) in COMPATIBLE mode
    Feb 5 11:25:06	kernel: ppc0: [ITHREAD]
    Feb 5 11:25:06	kernel: ppbus0: <parallel port="" bus="">on ppc0
    Feb 5 11:25:06	kernel: plip0: <plip network="" interface="">on ppbus0
    Feb 5 11:25:06	kernel: plip0: [ITHREAD]
    Feb 5 11:25:06	kernel: lpt0: <printer>on ppbus0
    Feb 5 11:25:06	kernel: lpt0: [ITHREAD]
    Feb 5 11:25:06	kernel: lpt0: Interrupt-driven port
    Feb 5 11:25:06	kernel: ppi0: <parallel i="" o="">on ppbus0
    Feb 5 11:25:06	kernel: uart0: <16550 or compatible> port 0x3f8-0x3ff irq 4 flags 0x10 on acpi0
    Feb 5 11:25:06	kernel: uart0: [FILTER]
    Feb 5 11:25:06	kernel: uart1: <16550 or compatible> port 0x2f8-0x2ff irq 3 on acpi0
    Feb 5 11:25:06	kernel: uart1: [FILTER]
    Feb 5 11:25:06	kernel: fdc0: <floppy drive="" controller="">port 0x3f0-0x3f5,0x3f7 irq 6 drq 2 on acpi0
    Feb 5 11:25:06	kernel: fdc0: [FILTER]
    Feb 5 11:25:06	kernel: fd0: <1440-KB 3.5" drive> on fdc0 drive 0
    Feb 5 11:25:06	kernel: pmtimer0 on isa0
    Feb 5 11:25:06	kernel: orm0: <isa option="" roms="">at iomem 0xc0000-0xc7fff,0xc8000-0xc8fff,0xc9000-0xc9fff,0xdc000-0xdffff,0xe0000-0xe7fff pnpid ORM0000 on isa0
    Feb 5 11:25:06	kernel: sc0: <system console="">at flags 0x100 on isa0
    Feb 5 11:25:06	kernel: sc0: VGA <16 virtual consoles, flags=0x300>
    Feb 5 11:25:06	kernel: vga0: <generic isa="" vga="">at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0
    Feb 5 11:25:06	kernel: acpi_throttle0: <acpi cpu="" throttling="">on cpu0
    Feb 5 11:25:06	kernel: Timecounter "TSC" frequency 2488273863 Hz quality 800
    Feb 5 11:25:06	kernel: Timecounters tick every 10.000 msec
    Feb 5 11:25:06	kernel: IPsec: Initialized Security Association Processing.
    Feb 5 11:25:06	kernel: ad0: 20480MB <vmware virtual="" ide="" hard="" drive="" 00000001="">at ata0-master UDMA33
    Feb 5 11:25:06	kernel: acd0: DVDR <vmware virtual="" ide="" cdrom="" drive="" 00000001="">at ata1-master UDMA33
    Feb 5 11:25:06	kernel: Trying to mount root from ufs:/dev/ad0s1a
    Feb 5 11:25:06	kernel: ad0: FAILURE - SETFEATURES 0x85 status=41 <ready,error>error=4 <aborted>Feb 5 11:25:07	dhclient: PREINIT
    Feb 5 11:25:07	dhclient: Starting delete_old_states()
    Feb 5 11:25:07	dhclient: Comparing IPs: Old: New:
    Feb 5 11:25:07	dhclient: Comparing Routers: Old: New:
    Feb 5 11:25:07	dhclient[6557]: DHCPREQUEST on em0 to 255.255.255.255 port 67
    Feb 5 11:25:07	dhclient[6557]: DHCPACK from 192.168.86.254
    Feb 5 11:25:07	dhclient: REBOOT
    Feb 5 11:25:07	dhclient: Starting delete_old_states()
    Feb 5 11:25:07	dhclient: Comparing IPs: Old: New: 192.168.86.132
    Feb 5 11:25:07	dhclient: Comparing Routers: Old: New: 192.168.86.2
    Feb 5 11:25:07	dhclient: Removing states through old gateway '' (new gateway '192.168.86.2')
    Feb 5 11:25:07	dhclient: Starting add_new_address()
    Feb 5 11:25:08	dhclient: ifconfig em0 inet 192.168.86.132 netmask 255.255.255.0 broadcast 192.168.86.255
    Feb 5 11:25:08	dhclient: New IP Address (em0): 192.168.86.132
    Feb 5 11:25:08	dhclient: New Subnet Mask (em0): 255.255.255.0
    Feb 5 11:25:08	dhclient: New Broadcast Address (em0): 192.168.86.255
    Feb 5 11:25:08	dhclient: New Routers (em0): 192.168.86.2
    Feb 5 11:25:08	dhclient: Adding new routes to interface: em0
    Feb 5 11:25:08	dhclient: /sbin/route add default 192.168.86.2
    Feb 5 11:25:08	dhclient: Creating resolv.conf
    Feb 5 11:25:08	dhclient[6557]: bound to 192.168.86.132 -- renewal in 900 seconds.
    Feb 5 11:25:08	php: : Accept router advertisements on interface em0
    Feb 5 11:25:08	dhcp6c[14467]: dhcp6_ctl_authinit: failed to open /usr/local/etc/dhcp6cctlkey: No such file or directory
    Feb 5 11:25:08	dhcp6c[14467]: client6_init: failed initialize control message authentication
    Feb 5 11:25:08	dhcp6c[14467]: client6_init: skip opening control port
    Feb 5 11:25:08	check_reload_status: rc.newwanip starting em0
    Feb 5 11:25:09	dhcp6c[14558]: client6_send: transmit failed: Can't assign requested address
    Feb 5 11:25:11	php: : rc.newwanip: Informational is starting em0.
    Feb 5 11:25:11	php: : rc.newwanip: on (IP address: 192.168.86.132) (interface: wan) (real interface: em0).
    Feb 5 11:25:11	php: : ROUTING: setting default route to 83.145.208.254
    Feb 5 11:25:11	php: : The command '/sbin/route change -inet default '83.145.208.254'' returned exit code '1', the output was 'route: writing to routing socket: Network is unreachable route: writing to routing socket: Network is unreachable change net default: gateway 83.145.208.254: Network is unreachable'
    Feb 5 11:25:12	check_reload_status: Reloading filter
    Feb 5 11:25:15	kernel: pflog0: promiscuous mode enabled
    Feb 5 11:25:18	php: : Resyncing OpenVPN instances for interface WAN.
    Feb 5 11:25:18	kernel: tun1: changing name to 'ovpns1'
    Feb 5 11:25:18	kernel: ovpns1: link state changed to UP
    Feb 5 11:25:18	check_reload_status: rc.newwanip starting ovpns1
    Feb 5 11:25:20	php: : Resyncing OpenVPN instances.
    Feb 5 11:25:20	dhcpleases: Could not deliver signal HUP to process because its pidfile does not exist, No such file or directory.
    Feb 5 11:25:20	kernel: ovpns1: link state changed to DOWN
    Feb 5 11:25:20	kernel: ovpns1: link state changed to UP
    Feb 5 11:25:21	php: : rc.newwanip: Informational is starting ovpns1.
    Feb 5 11:25:21	php: : rc.newwanip: on (IP address: 192.168.37.201) (interface: ) (real interface: ovpns1).
    Feb 5 11:25:21	php: : pfSense package system has detected an ip change -> ... Restarting packages.
    Feb 5 11:25:21	check_reload_status: Starting packages
    Feb 5 11:25:23	php: : ROUTING: setting default route to 83.145.208.254
    Feb 5 11:25:23	php: : The command '/sbin/route change -inet default '83.145.208.254'' returned exit code '1', the output was 'route: writing to routing socket: Network is unreachable route: writing to routing socket: Network is unreachable change net default: gateway 83.145.208.254: Network is unreachable'
    Feb 5 11:25:23	dhcpleases: Could not deliver signal HUP to process because its pidfile does not exist, No such file or directory.
    Feb 5 11:25:23	dhcpleases: kqueue error: unkown
    Feb 5 11:25:23	check_reload_status: Updating all dyndns
    Feb 5 11:25:24	php: : Restarting/Starting all packages.
    Feb 5 11:25:26	check_reload_status: Restarting ipsec tunnels
    Feb 5 11:25:27	php: : The command '/usr/local/etc/rc.d/radiusd.sh stop' returned exit code '1', the output was 'radiusd not running?'
    Feb 5 11:25:27	php: : The command '/usr/local/etc/rc.d/radiusd.sh stop' returned exit code '1', the output was 'radiusd not running?'
    Feb 5 11:25:28	php: : Creating rrd update script
    Feb 5 11:25:28	php: : miniupnpd: Starting service on interface: lan
    Feb 5 11:25:28	miniupnpd[71662]: HTTP listening on port 2189
    Feb 5 11:25:28	miniupnpd[71662]: Listening for NAT-PMP traffic on port 5351
    Feb 5 11:25:29	php: : Restarting/Starting all packages.
    Feb 5 11:25:29	php: : The command '/usr/local/etc/rc.d/radiusd.sh stop' returned exit code '1', the output was 'radiusd not running?'
    Feb 5 11:25:31	php: : The command '/usr/local/etc/rc.d/radiusd.sh stop' returned exit code '1', the output was 'radiusd not running?'
    Feb 5 11:25:31	php: : The command '/usr/local/etc/rc.d/radiusd.sh stop' returned exit code '1', the output was 'radiusd not running?'
    Feb 5 11:25:32	php: : The command '/usr/local/etc/rc.d/radiusd.sh stop' returned exit code '1', the output was 'radiusd not running?'
    Feb 5 11:25:33	php: : The command '/usr/local/etc/rc.d/radiusd.sh stop' returned exit code '1', the output was 'radiusd not running?'
    Feb 5 11:25:34	php: : The command '/usr/local/etc/rc.d/radiusd.sh stop' returned exit code '1', the output was 'radiusd not running?'
    Feb 5 11:25:36	php: : The command '/usr/local/etc/rc.d/radiusd.sh stop' returned exit code '1', the output was 'radiusd not running?'
    Feb 5 11:25:37	php: : The command '/usr/local/etc/rc.d/radiusd.sh stop' returned exit code '1', the output was 'radiusd not running?'
    Feb 5 11:25:38	php: : The command '/usr/local/etc/rc.d/radiusd.sh stop' returned exit code '1', the output was 'radiusd not running?'
    Feb 5 11:25:39	php: : The command '/usr/local/etc/rc.d/radiusd.sh stop' returned exit code '1', the output was 'radiusd not running?'
    Feb 5 11:25:40	radiusd[47567]: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked
    Feb 5 11:25:40	radiusd[47567]: rlm_sql (sql): Attempting to connect to radius@192.168.10.10:3306/radius
    Feb 5 11:25:40	radiusd[47567]: rlm_sql (sql): Attempting to connect rlm_sql_mysql #0
    Feb 5 11:25:40	radiusd[47567]: rlm_sql_mysql: Starting connect to MySQL server for #0
    Feb 5 11:25:40	radiusd[47567]: rlm_sql (sql): Connected new DB handle, #0
    Feb 5 11:25:40	radiusd[47567]: rlm_sql (sql): Attempting to connect rlm_sql_mysql #1
    Feb 5 11:25:40	radiusd[47567]: rlm_sql_mysql: Starting connect to MySQL server for #1
    Feb 5 11:25:40	php: : The command '/usr/local/etc/rc.d/radiusd.sh stop' returned exit code '1', the output was 'radiusd not running?'
    Feb 5 11:25:41	php: : The command '/usr/local/etc/rc.d/radiusd.sh stop' returned exit code '1', the output was 'radiusd not running?'
    Feb 5 11:25:43	radiusd[60380]: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked
    Feb 5 11:25:43	radiusd[60380]: rlm_sql (sql): Attempting to connect to radius@192.168.10.10:3306/radius
    Feb 5 11:25:43	radiusd[60380]: rlm_sql (sql): Attempting to connect rlm_sql_mysql #0
    Feb 5 11:25:43	radiusd[60380]: rlm_sql_mysql: Starting connect to MySQL server for #0
    Feb 5 11:25:43	php: : The command '/usr/local/etc/rc.d/radiusd.sh stop' returned exit code '1', the output was 'radiusd not running?'
    Feb 5 11:25:44	php: : The command '/usr/local/etc/rc.d/radiusd.sh stop' returned exit code '1', the output was 'radiusd not running?'
    Feb 5 11:25:45	php: : The command '/usr/local/etc/rc.d/radiusd.sh stop' returned exit code '1', the output was 'radiusd not running?'
    Feb 5 11:25:46	radiusd[75792]: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked
    Feb 5 11:25:46	radiusd[75792]: rlm_sql (sql): Attempting to connect to radius@192.168.10.10:3306/radius
    Feb 5 11:25:46	radiusd[75792]: rlm_sql (sql): Attempting to connect rlm_sql_mysql #0
    Feb 5 11:25:46	radiusd[75792]: rlm_sql_mysql: Starting connect to MySQL server for #0
    Feb 5 11:25:46	radiusd[75792]: rlm_sql (sql): Connected new DB handle, #0
    Feb 5 11:25:46	radiusd[75792]: rlm_sql (sql): Attempting to connect rlm_sql_mysql #1
    Feb 5 11:25:46	radiusd[75792]: rlm_sql_mysql: Starting connect to MySQL server for #1
    Feb 5 11:25:46	radiusd[75792]: rlm_sql (sql): Connected new DB handle, #1
    Feb 5 11:25:46	radiusd[75792]: rlm_sql (sql): Attempting to connect rlm_sql_mysql #2
    Feb 5 11:25:46	radiusd[75792]: rlm_sql_mysql: Starting connect to MySQL server for #2
    Feb 5 11:25:46	radiusd[75792]: rlm_sql (sql): Connected new DB handle, #2
    Feb 5 11:25:46	radiusd[75792]: rlm_sql (sql): Attempting to connect rlm_sql_mysql #3
    Feb 5 11:25:46	radiusd[75792]: rlm_sql_mysql: Starting connect to MySQL server for #3
    Feb 5 11:25:46	radiusd[75792]: rlm_sql (sql): Connected new DB handle, #3
    Feb 5 11:25:46	radiusd[75792]: rlm_sql (sql): Attempting to connect rlm_sql_mysql #4
    Feb 5 11:25:46	radiusd[75792]: rlm_sql_mysql: Starting connect to MySQL server for #4
    Feb 5 11:25:46	radiusd[75792]: rlm_sql (sql): Connected new DB handle, #4
    Feb 5 11:25:46	radiusd[75792]: Loaded virtual server <default>Feb 5 11:25:46	radiusd[76076]: Ready to process requests.
    Feb 5 11:25:47	radiusd[76076]: Signalled to terminate
    Feb 5 11:25:47	radiusd[76076]: Exiting normally.
    Feb 5 11:25:47	radiusd[76076]: rlm_sql (sql): Closing sqlsocket 4
    Feb 5 11:25:47	radiusd[76076]: rlm_sql (sql): Closing sqlsocket 3
    Feb 5 11:25:47	radiusd[76076]: rlm_sql (sql): Closing sqlsocket 2
    Feb 5 11:25:47	radiusd[76076]: rlm_sql (sql): Closing sqlsocket 1
    Feb 5 11:25:47	radiusd[76076]: rlm_sql (sql): Closing sqlsocket 0
    Feb 5 11:25:47	php: : The command '/usr/local/etc/rc.d/radiusd.sh stop' returned exit code '1', the output was 'radiusd not running?'
    Feb 5 11:25:48	radiusd[84135]: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked
    Feb 5 11:25:48	radiusd[84135]: rlm_sql (sql): Attempting to connect to radius@192.168.10.10:3306/radius
    Feb 5 11:25:48	radiusd[84135]: rlm_sql (sql): Attempting to connect rlm_sql_mysql #0
    Feb 5 11:25:48	radiusd[84135]: rlm_sql_mysql: Starting connect to MySQL server for #0
    Feb 5 11:25:48	radiusd[84135]: rlm_sql (sql): Connected new DB handle, #0
    Feb 5 11:25:48	radiusd[84135]: rlm_sql (sql): Attempting to connect rlm_sql_mysql #1
    Feb 5 11:25:48	radiusd[84135]: rlm_sql_mysql: Starting connect to MySQL server for #1
    Feb 5 11:25:48	radiusd[84135]: rlm_sql (sql): Connected new DB handle, #1
    Feb 5 11:25:48	radiusd[84135]: rlm_sql (sql): Attempting to connect rlm_sql_mysql #2
    Feb 5 11:25:48	radiusd[84135]: rlm_sql_mysql: Starting connect to MySQL server for #2
    Feb 5 11:25:48	radiusd[84135]: rlm_sql (sql): Connected new DB handle, #2
    Feb 5 11:25:48	radiusd[84135]: rlm_sql (sql): Attempting to connect rlm_sql_mysql #3
    Feb 5 11:25:48	radiusd[84135]: rlm_sql_mysql: Starting connect to MySQL server for #3
    Feb 5 11:25:48	radiusd[84135]: rlm_sql (sql): Connected new DB handle, #3
    Feb 5 11:25:48	radiusd[84135]: rlm_sql (sql): Attempting to connect rlm_sql_mysql #4
    Feb 5 11:25:48	radiusd[84135]: rlm_sql_mysql: Starting connect to MySQL server for #4
    Feb 5 11:25:48	radiusd[84135]: rlm_sql (sql): Connected new DB handle, #4
    Feb 5 11:25:48	radiusd[84135]: Loaded virtual server <default>Feb 5 11:25:48	radiusd[84242]: Ready to process requests.
    Feb 5 11:25:52	login: login on ttyv0 as root
    Feb 5 11:25:52	sshlockout[91168]: sshlockout/webConfigurator v3.0 starting up
    Feb 5 11:40:47	dhclient[13939]: DHCPREQUEST on em0 to 192.168.86.254 port 67
    Feb 5 11:40:47	dhclient[13939]: DHCPACK from 192.168.86.254
    Feb 5 11:40:47	dhclient: RENEW
    Feb 5 11:40:47	dhclient: Creating resolv.conf
    Feb 5 11:40:47	dhclient[13939]: bound to 192.168.86.132 -- renewal in 900 seconds.
    Feb 5 11:45:39	php: /diag_logs.php: Successful login for user 'admin' from: 192.168.10.118
    Feb 5 11:45:39	php: /diag_logs.php: Successful login for user 'admin' from: 192.168.10.118
    Feb 5 11:48:59	check_reload_status: Syncing firewall
    Feb 5 11:49:00	syslogd: exiting on signal 15
    Feb 5 11:49:00	syslogd: kernel boot file is /boot/kernel/kernel
    Feb 5 11:49:00	kernel: pflog0: promiscuous mode disabled</default></default></aborted></ready,error></vmware></vmware></acpi></generic></system></isa></floppy></parallel></printer></plip></parallel></parallel></ps></at></keyboard></at></ac></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></acpi></intel(r)></intel(r)></acpi></acpi></vga-compatible></bridge></ata></ata></intel></isa></pci-isa></acpi></acpi></acpi></acpi></acpi></intel></software></version></ptltd></lahf></nx,lm></sse3,ssse3,cx16,x2apic,hv></fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,pse36,dts,mmx,fxsr,sse,sse2,ss> 
    


  • Hmm, then you might be facing a different problem or my first entry is unrelated to remote syslogging. I always get:

    syslogd: sendto: Network is unreachable
    


  • Yes, it's something diffrent, because now my test server is sending events to remote syslog.

    Last events from this server before today were at 2013-01-25 10:55:43, so after that time I might have abused my test server too much…



  • Hi,

    I have the same problem with 2.1 (02 feb build).
    My syslog server is directly attached to a static NIC of the pfsense box, not using IPv6 but it's not globally disabled. WAN link is pppoe though, if that matter.

    After a fresh reboot of the pfsense box:

    • nothing on syslog server.

    • if I do some modification on the pfsense syslog parameters page and click on save, I get in remote syslog:

    Feb  8 17:04:02 192.168.10.254 syslogd: restart
    Feb  8 17:04:02 192.168.10.254 syslogd: kernel boot file is /boot/kernel/kernel
    Feb  8 17:04:02 192.168.10.254 kernel: pflog0: promiscuous mode disabled
    Feb  8 17:04:02 192.168.10.254 pf:
    
    • if I go into a shell on pfsense box, stop syslogd process and restart it, issue is fixed.

    Additionnal data:

    • Seeing the "syslogd: sendto: Network is unreachable" message in pfsense logs.

    • no package installed

    • Config:

            <syslog><nentries>50</nentries>
                    <logall><remoteserver>192.168.10.1</remoteserver>
                    <remoteserver2><remoteserver3><enable><reverse><nologdefaultblock></nologdefaultblock></reverse></enable></remoteserver3></remoteserver2></logall></syslog> 
    

  • Rebel Alliance Developer Netgate

    Try editing this file on your firewall and remove the if statement and closing bracket, so it just runs system_syslogd_start(); no matter what.
    See if that helps.



  • Hi jimp,
    which file should we edit?


  • Rebel Alliance Developer Netgate



  • Fine, that works for me.


  • Rebel Alliance Developer Netgate

    So that change fixes the problem?

    Or you're OK with testing the change?



  • Oh, sorry! I meant to say, the change worked for my setup (ALIX Board), it fixes the problem. And thanks for looking into this!


  • Rebel Alliance Developer Netgate

    OK, I took the if statement out and updated the comment. Should be in later snapshots.



  • I've got the same problem with 2.0.3, presumably I could try the same fix?  Thanks, Adrian


  • Rebel Alliance Developer Netgate

    @abrooks:

    I've got the same problem with 2.0.3, presumably I could try the same fix?  Thanks, Adrian

    Yes if the same test/code is there on 2.0.x then the same fix should work.



  • Thanks - I'll give it a try in a couple of days and let you know.  Adrian.


Log in to reply