Timestamps in /var/log/messages

I have noticed an inconsistency of the timestamps in var/log/messages (Turris os 3.5.2).
Is this my mis-configuration or a bug? Does anyone else experiences this?

2017-02-05T11:26:01+02:00 info /usr/sbin/cron[19203]: (root) CMD (nethist_stats.lua)
2017-02-05T11:26:01+02:00 info /usr/sbin/cron[19204]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-02-05T13:26:16+02:00 info dnsmasq-dhcp[3482]: DHCPDISCOVER(br-lan) 36:b3:dc:13:30:e4 
2017-02-05T13:26:16+02:00 info dnsmasq-dhcp[3482]: DHCPOFFER(br-lan) 10.0.10.2 36:b3:dc:13:30:e4 
2017-02-05T13:26:22+02:00 info dnsmasq-dhcp[3482]: DHCPDISCOVER(br-lan) 36:b3:dc:13:30:e4 
2017-02-05T13:26:22+02:00 info dnsmasq-dhcp[3482]: DHCPOFFER(br-lan) 10.0.10.2 36:b3:dc:13:30:e4 
2017-02-05T13:26:29+02:00 info dnsmasq-dhcp[3482]: DHCPDISCOVER(br-lan) 36:b3:dc:13:30:e4 
2017-02-05T13:26:29+02:00 info dnsmasq-dhcp[3482]: DHCPOFFER(br-lan) 10.0.10.2 36:b3:dc:13:30:e4 
2017-02-05T13:26:48+02:00 info dnsmasq-dhcp[3482]: DHCPDISCOVER(br-lan) 36:b3:dc:13:30:e4 
2017-02-05T13:26:48+02:00 info dnsmasq-dhcp[3482]: DHCPOFFER(br-lan) 10.0.10.2 36:b3:dc:13:30:e4 
2017-02-05T11:27:01+02:00 info /usr/sbin/cron[19364]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-02-05T13:27:01+02:00 info dnsmasq-dhcp[3482]: DHCPDISCOVER(br-lan) 36:b3:dc:13:30:e4 
2017-02-05T13:27:01+02:00 info dnsmasq-dhcp[3482]: DHCPOFFER(br-lan) 10.0.10.2 36:b3:dc:13:30:e4 
2017-02-05T11:28:01+02:00 info /usr/sbin/cron[19530]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-02-05T11:28:01+02:00 info /usr/sbin/cron[19529]: (root) CMD (nethist_stats.lua)
2017-02-05T11:29:01+02:00 info /usr/sbin/cron[19694]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-02-05T11:30:01+02:00 info /usr/sbin/cron[19843]: (root) CMD (nethist_stats.lua)
2017-02-05T11:30:01+02:00 info /usr/sbin/cron[19847]: (root) CMD (/usr/bin/get-api-crl)
2017-02-05T11:30:01+02:00 info /usr/sbin/cron[19848]: (root) CMD (/sbin/fan_ctrl.sh)
2017-02-05T11:30:01+02:00 info /usr/sbin/cron[19839]: (root) CMD (/usr/bin/watchdog.sh)
2017-02-05T11:30:01+02:00 info /usr/sbin/cron[19849]: (root) CMD (/usr/share/nikola/bin/nikola.sh)
2017-02-05T11:30:01+02:00 info /usr/sbin/cron[19856]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-02-05T11:30:01+02:00 info /usr/sbin/cron[19853]: (root) CMD (vnstat -u)
2017-02-05T11:30:01+02:00 info /usr/sbin/cron[19850]: (root) CMD (majordomo_db.sh downsize)
2017-02-05T11:30:01+02:00 info /usr/sbin/cron[19851]: (root) CMD (   /usr/bin/notifier)
2017-02-05T11:30:01+02:00 info /usr/sbin/cron[19846]: (root) MAIL (mailed 204 bytes of output but got status 0x0001)
2017-02-05T13:30:02+02:00 info nikola[]: (v41) recognized WAN interfaces: 3g-Lte, eth1, lo
2017-02-05T11:30:13+02:00 warning watchdog[]: Restarted nethist
2017-02-05T13:30:54+02:00 info nikola[]: (v41) Establishing connection took 3.940789 seconds
2017-02-05T13:30:54+02:00 info nikola[]: (v41) Logrotate took 0.005030 seconds
2017-02-05T13:30:54+02:00 info nikola[]: (v41) Syslog parsing took 0.000082 seconds
2017-02-05T13:30:59+02:00 info nikola[]: (v41) Session init took 4.766844 seconds
2017-02-05T13:30:59+02:00 info nikola[]: (v41) Records parsed: 0
2017-02-05T13:30:59+02:00 info nikola[]: (v41) Records after filtering: 0
2017-02-05T13:30:59+02:00 info nikola[]: (v41) Records filtering took 0.000530 seconds
2017-02-05T11:31:01+02:00 info /usr/sbin/cron[20105]: (root) CMD (/usr/bin/rainbow_button_sync.sh)

Unfortunately, it is common issue since beginning of Omnia. :frowning:

Yes, its is. Did someone report it to tech.support(at)turris(dot)cz?

Common issue … hmmm. Very interesting!

I personally know about this. It seems like it is problem in utc vs time zone time stamping. I have it in my todo list, but it is way down. It is little bit annoying, but it seems harmless so I am prioritizing for example updater bugs. So if anyone have time and looks into this problem, it would be awesome. O:-)

3 Likes

I was about to file this as a bug myself. It’s surprising and crass. In my log file it simply looks like some utilities are double counting the UTC time offset, namely adding and reporting it. Check it out below. Basically it’s about 16:20 here (and I’m at +10:00 hours from UTC here), and some report 06:20+10:00 (correct) and others 16:20+10:00 double counting. This is rather poor show really and ought to be fixed. Seems kernel and dnsmasq are suffering the glitch. kernel is a surprise.

2017-05-30T16:22:04+10:00 notice syslog-ng[1907]: syslog-ng starting up; version='3.0.9'
2017-05-30T16:22:05+10:00 info kernel[]: [    8.128642] xhci-hcd f10f0000.usb3: irq 46, io mem 0xf10f0000
2017-05-30T16:22:05+10:00 info kernel[]: [    8.134659] hub 2-0:1.0: USB hub found
2017-05-30T16:22:05+10:00 info kernel[]: [    8.138432] hub 2-0:1.0: 1 port detected
2017-05-30T16:22:05+10:00 info kernel[]: [    8.142470] xhci-hcd f10f0000.usb3: xHCI Host Controller
2017-05-30T16:22:05+10:00 info kernel[]: [    8.147799] xhci-hcd f10f0000.usb3: new USB bus registered, assigned bus number 3
2017-05-30T16:22:05+10:00 info kernel[]: [    8.155335] usb usb3: We don't know the algorithms for LPM for this host, disabling LPM.
2017-05-30T16:22:05+10:00 info kernel[]: [    8.163656] hub 3-0:1.0: USB hub found
2017-05-30T16:22:05+10:00 info kernel[]: [    8.167424] hub 3-0:1.0: 1 port detected
2017-05-30T16:22:05+10:00 info kernel[]: [    8.171533] xhci-hcd f10f8000.usb3: xHCI Host Controller
2017-05-30T16:22:05+10:00 info kernel[]: [    8.176864] xhci-hcd f10f8000.usb3: new USB bus registered, assigned bus number 4
2017-05-30T06:22:05+10:00 info lcollect[1819]: Loading plugin library libplugin_lcollect_majordomo_28.so
2017-05-30T06:22:05+10:00 info lcollect[1819]: Installing plugin Majordomo with api version 0
2017-05-30T06:22:05+10:00 info lcollect[1819]: Running the main loop
2017-05-30T06:22:06+10:00 notice netifd[]: radio0 (1803): command failed: Not supported (-95)
2017-05-30T06:22:06+10:00 notice netifd[]: radio0 (1803): Configuration file: /var/run/hostapd-phy0.conf
2017-05-30T06:22:06+10:00 notice netifd[]: radio1 (1804): Configuration file: /var/run/hostapd-phy1.conf
2017-05-30T06:22:07+10:00 notice netifd[]: radio1 (1804): wlan1: interface state UNINITIALIZED->COUNTRY_UPDATE
2017-05-30T06:22:07+10:00 notice netifd[]: radio1 (1804): Using interface wlan1 with hwaddr 04:f0:21:23:15:70 and ssid "Cerberus"
2017-05-30T06:22:07+10:00 notice netifd[]: Network device 'eth0' link is up
2017-05-30T06:22:07+10:00 notice netifd[]: Network device 'eth2' link is up
2017-05-30T16:22:10+10:00 info kernel[]: [    8.184464] xhci-hcd f10f8000.usb3: hcc params 0x0a000990 hci version 0x100 quirks 0x00010010
2017-05-30T16:22:10+10:00 info kernel[]: [    8.193029] xhci-hcd f10f8000.usb3: irq 47, io mem 0xf10f8000
2017-05-30T16:22:10+10:00 info kernel[]: [    8.199009] hub 4-0:1.0: USB hub found
2017-05-30T16:22:10+10:00 info kernel[]: [    8.202788] hub 4-0:1.0: 1 port detected
2017-05-30T16:22:10+10:00 info kernel[]: [    8.206810] xhci-hcd f10f8000.usb3: xHCI Host Controller
2017-05-30T16:22:10+10:00 info kernel[]: [    8.212144] xhci-hcd f10f8000.usb3: new USB bus registered, assigned bus number 5
2017-05-30T16:22:10+10:00 info kernel[]: [    8.219671] usb usb5: We don't know the algorithms for LPM for this host, disabling LPM.
2017-05-30T16:22:10+10:00 info kernel[]: [    8.227993] hub 5-0:1.0: USB hub found
2017-05-30T16:22:10+10:00 info kernel[]: [    8.231768] hub 5-0:1.0: 1 port detected
2017-05-30T16:22:10+10:00 info kernel[]: [    8.237031] usbcore: registered new interface driver usb-storage
2017-05-30T06:22:07+10:00 notice netifd[]: Bridge 'br-lan' link is up
2017-05-30T16:22:08+10:00 info dnsmasq[2056]: started, version 2.73 DNS disabled
2017-05-30T16:22:10+10:00 info dnsmasq[2056]: compile time options: IPv6 GNU-getopt no-DBus no-i18n no-IDN DHCP no-DHCPv6 no-Lua TFTP no-conntrack no-ipset no-auth no-DNSSEC loop-detect inotify
2017-05-30T16:22:10+10:00 info dnsmasq[2056]: DNS service limited to local subnets
2017-05-30T16:22:10+10:00 info dnsmasq-dhcp[2056]: DHCP, IP range 192.168.0.101 -- 192.168.0.250, lease time 12h
2017-05-30T16:22:10+10:00 err dnsmasq-dhcp[2056]: bad line at /etc/ethers line 1
2017-05-30T16:22:10+10:00 err dnsmasq-dhcp[2056]: bad line at /etc/ethers line 2
2017-05-30T16:22:10+10:00 err dnsmasq-dhcp[2056]: bad line at /etc/ethers line 3
2017-05-30T16:22:10+10:00 info dnsmasq-dhcp[2056]: read /etc/ethers - 0 addresses
2017-05-30T06:22:09+10:00 warning lcollect[1819]: epoll_wait on 4 interrupted, retry
2017-05-30T16:22:10+10:00 info kernel[]:    9.130724] init: - preinit -
2017-05-30T16:22:10+10:00 notice kernel[]:   12.204634] mount_root: mounting /dev/root
2017-05-30T16:22:10+10:00 info kernel[]: [   12.313904] BTRFS info (device mmcblk0p1): disk space caching is enabled
2017-05-30T16:22:10+10:00 info kernel[]:   12.321094] mount_root: loading kmods from internal overlay
2017-05-30T16:22:10+10:00 info kernel[]:   12.532546] block: attempting to load /etc/config/fstab
2017-05-30T16:22:10+10:00 info kernel[]:   12.538645] block: extroot: not configured
2017-05-30T16:22:10+10:00 info kernel[]:   12.545131] procd: - early -
2017-05-30T16:22:10+10:00 notice kernel[]: [   12.644126] random: jshn: uninitialized urandom read (4 bytes read, 42 bits of entropy available)
2017-05-30T16:22:10+10:00 notice kernel[]: [   12.671314] random: jshn: uninitialized urandom read (4 bytes read, 43 bits of entropy available)
2017-05-30T16:22:10+10:00 notice kernel[]: [   12.706792] random: jshn: uninitialized urandom read (4 bytes read, 43 bits of entropy available)
2017-05-30T06:22:10+10:00 info lcollect[1819]: Reconfiguring
2017-05-30T06:22:09+10:00 notice netifd[]: radio0 (1803): wlan0: interface state UNINITIALIZED->COUNTRY_UPDATE
2017-05-30T06:22:10+10:00 notice netifd[]: radio0 (1803): Using interface wlan0 with hwaddr 04:f0:21:1c:bc:07 and ssid "Cerberus Turbo"
2017-05-30T06:22:10+10:00 notice netifd[]: radio0 (1803): wlan0: interface state COUNTRY_UPDATE->ENABLED
2017-05-30T06:22:10+10:00 notice netifd[]: radio0 (1803): wlan0: AP-ENABLED 
2017-05-30T06:22:10+10:00 notice netifd[]: radio1 (1804): wlan1: interface state COUNTRY_UPDATE->ENABLED
2017-05-30T06:22:10+10:00 notice netifd[]: radio1 (1804): wlan1: AP-ENABLED 
2017-05-30T06:22:10+10:00 notice netifd[]: Network device 'eth1' link is up
2017-05-30T06:22:10+10:00 notice netifd[]: Interface 'wan' has link connectivity 
2017-05-30T06:22:10+10:00 notice netifd[]: Interface 'wan' is setting up now
2017-05-30T16:22:10+10:00 notice kernel[]: [   12.731505] random: jshn: uninitialized urandom read (4 bytes read, 43 bits of entropy available)
2017-05-30T16:22:10+10:00 notice kernel[]: [   12.767146] random: jshn: uninitialized urandom read (4 bytes read, 43 bits of entropy available)
2017-05-30T16:22:10+10:00 notice kernel[]: [   12.791721] random: jshn: uninitialized urandom read (4 bytes read, 43 bits of entropy available)
2017-05-30T16:22:10+10:00 notice kernel[]: [   12.827230] random: jshn: uninitialized urandom read (4 bytes read, 43 bits of entropy available)
2017-05-30T16:22:10+10:00 notice kernel[]: [   12.851764] random: jshn: uninitialized urandom read (4 bytes read, 43 bits of entropy available)
2017-05-30T16:22:10+10:00 notice kernel[]: [   12.887213] random: jshn: uninitialized urandom read (4 bytes read, 43 bits of entropy available)
2017-05-30T16:22:10+10:00 notice kernel[]: [   12.911834] random: jshn: uninitialized urandom read (4 bytes read, 43 bits of entropy available)
2017-05-30T16:22:10+10:00 info kernel[]:   13.113765] procd: - watchdog -
2017-05-30T16:22:10+10:00 info kernel[]:   13.117146] procd: - ubus -
2017-05-30T16:22:10+10:00 info kernel[]:   14.131706] procd: - init -
2017-05-30T16:22:10+10:00 info kernel[]: [   14.196501] marvell-cesa f1090000.crypto: CESA device successfully registered
2017-05-30T16:22:10+10:00 info kernel[]: [   14.209256] NET: Registered protocol family 38
2017-05-30T16:22:10+10:00 info kernel[]: [   14.226349] md: linear personality registered for level -1
2017-05-30T16:22:10+10:00 info kernel[]: [   14.232271] md: raid0 personality registered for level 0
2017-05-30T16:22:10+10:00 info kernel[]: [   14.238295] md: raid1 personality registered for level 1
2017-05-30T16:22:10+10:00 info kernel[]: [   14.244751] md: raid10 personality registered for level 10
2017-05-30T16:22:10+10:00 info kernel[]: [   14.250671] async_tx: api initialized (async)
2017-05-30T16:22:10+10:00 info kernel[]: [   14.258069] md: raid6 personality registered for level 6
2017-05-30T16:22:10+10:00 info kernel[]: [   14.263424] md: raid5 personality registered for level 5
2017-05-30T16:22:10+10:00 info kernel[]: [   14.268747] md: raid4 personality registered for level 4
2017-05-30T16:22:10+10:00 notice kernel[]: [   14.276047] FS-Cache: Loaded
2017-05-30T16:22:10+10:00 info kernel[]: [   14.279402] md: multipath personality registered for level -4
2017-05-30T16:22:10+10:00 info kernel[]: [   14.286403] NET: Registered protocol family 8
2017-05-30T16:22:10+10:00 info kernel[]: [   14.290797] NET: Registered protocol family 20
2017-05-30T16:22:10+10:00 info kernel[]: [   14.299066] device-mapper: ioctl: 4.34.0-ioctl (2015-10-28) initialised: dm-devel@redhat.com
2017-05-30T16:22:10+10:00 notice kernel[]: [   14.310043] Key type dns_resolver registered
2017-05-30T16:22:10+10:00 info kernel[]: [   14.317234] NET: Registered protocol family 33
2017-05-30T16:22:10+10:00 notice kernel[]: [   14.321713] Key type rxrpc registered
2017-05-30T16:22:10+10:00 notice kernel[]: [   14.325382] Key type rxrpc_s registered
2017-05-30T16:22:10+10:00 info kernel[]: [   14.332344] kAFS: Red Hat AFS client v0.1 registering.
2017-05-30T16:22:10+10:00 notice kernel[]: [   14.337535] FS-Cache: Netfs 'afs' registered for caching
2017-05-30T16:22:10+10:00 info kernel[]: [   14.371840] RPC: Registered named UNIX socket transport module.
2017-05-30T16:22:10+10:00 info kernel[]: [   14.377778] RPC: Registered udp transport module.
2017-05-30T16:22:10+10:00 info kernel[]: [   14.382512] RPC: Registered tcp transport module.
2017-05-30T16:22:10+10:00 info kernel[]: [   14.387226] RPC: Registered tcp NFSv4.1 backchannel transport module.
2017-05-30T16:22:10+10:00 info kernel[]: [   14.397802] ntfs: driver 2.1.32 [Flags: R/O MODULE].
2017-05-30T16:22:10+10:00 notice kernel[]: [   14.407685] RxRPC: Registered security type 2 'rxkad'
2017-05-30T16:22:10+10:00 info kernel[]: [   14.424536] tun: Universal TUN/TAP device driver, 1.6
2017-05-30T16:22:10+10:00 info kernel[]: [   14.429603] tun: (C) 1999-2004 Max Krasnyansky <maxk@qualcomm.com>
2017-05-30T16:22:10+10:00 info kernel[]: [   14.440096] sit: IPv6 over IPv4 tunneling driver
2017-05-30T16:22:10+10:00 info kernel[]: [   14.447046] gre: GRE over IPv4 demultiplexor driver
2017-05-30T16:22:10+10:00 info kernel[]: [   14.452673] ip_gre: GRE over IPv4 tunneling driver
2017-05-30T16:22:10+10:00 info kernel[]: [   14.473016] Installing knfsd (copyright (C) 1996 okir@monad.swb.de).
2017-05-30T16:22:10+10:00 info kernel[]: [   14.481610] PPP generic driver version 2.4.2
2017-05-30T16:22:10+10:00 info kernel[]: [   14.489115] ip6_tables: (C) 2000-2006 Netfilter Core Team
2017-05-30T16:22:10+10:00 info kernel[]: [   14.498719] cryptodev: driver 1.8 loaded.
2017-05-30T16:22:10+10:00 info kernel[]: [   14.507021] Loading modules backported from Linux version wt-2016-10-03-1-g6fcb1a6
2017-05-30T16:22:10+10:00 info kernel[]: [   14.514632] Backport generated by backports.git backports-20160324-9-g0e38f5c
2017-05-30T16:22:10+10:00 info kernel[]: [   14.593960] pci 0000:00:02.0: enabling device (0140 -> 0142)
2017-05-30T16:22:10+10:00 info kernel[]: [   14.599813] ath10k_pci 0000:02:00.0: pci irq msi oper_irq_mode 2 irq_mode 0 reset_mode 0
2017-05-30T16:22:10+10:00 warning kernel[]: [   14.774064] ath10k_pci 0000:02:00.0: Direct firmware load for ath10k/pre-cal-pci-0000:02:00.0.bin failed with error -2
2017-05-30T16:22:10+10:00 warning kernel[]: [   14.784804] ath10k_pci 0000:02:00.0: Falling back to user helper
2017-05-30T16:22:10+10:00 err kernel[]: [   14.794539] firmware ath10k!pre-cal-pci-0000:02:00.0.bin: firmware_loading_store: map pages failed
2017-05-30T16:22:10+10:00 warning kernel[]: [   14.803660] ath10k_pci 0000:02:00.0: Direct firmware load for ath10k/cal-pci-0000:02:00.0.bin failed with error -2
2017-05-30T16:22:10+10:00 warning kernel[]: [   14.814048] ath10k_pci 0000:02:00.0: Falling back to user helper
2017-05-30T16:22:10+10:00 err kernel[]: [   14.823580] firmware ath10k!cal-pci-0000:02:00.0.bin: firmware_loading_store: map pages failed
2017-05-30T16:22:10+10:00 info kernel[]: [   14.840258] ath10k_pci 0000:02:00.0: qca988x hw2.0 target 0x4100016c chip_id 0x043202ff sub 0000:0000
2017-05-30T16:22:10+10:00 info kernel[]: [   14.849528] ath10k_pci 0000:02:00.0: kconfig debug 0 debugfs 1 tracing 0 dfs 1 testmode 1
2017-05-30T16:22:10+10:00 info kernel[]: [   14.859143] ath10k_pci 0000:02:00.0: firmware ver 10.2.4.70.54 api 5 features no-p2p,raw-mode,mfp crc32 9d340dd9
2017-05-30T16:22:10+10:00 warning kernel[]: [   14.909466] ath10k_pci 0000:02:00.0: Direct firmware load for ath10k/QCA988X/hw2.0/board-2.bin failed with error -2
2017-05-30T16:22:10+10:00 warning kernel[]: [   14.919935] ath10k_pci 0000:02:00.0: Falling back to user helper
2017-05-30T16:22:10+10:00 err kernel[]: [   14.929572] firmware ath10k!QCA988X!hw2.0!board-2.bin: firmware_loading_store: map pages failed
2017-05-30T16:22:10+10:00 info kernel[]: [   14.938516] ath10k_pci 0000:02:00.0: board_file api 1 bmi_id N/A crc32 bebc7c08
2017-05-30T16:22:10+10:00 info kernel[]: [   16.081484] ath10k_pci 0000:02:00.0: htt-ver 2.1 wmi-op 5 htt-op 2 cal otp max-sta 128 raw 0 hwcrypto 1
2017-05-30T16:22:10+10:00 debug kernel[]: [   16.171799] ath: EEPROM regdomain: 0x0
2017-05-30T16:22:10+10:00 debug kernel[]: [   16.171804] ath: EEPROM indicates default country code should be used
2017-05-30T16:22:10+10:00 debug kernel[]: [   16.171807] ath: doing EEPROM country->regdmn map search
2017-05-30T16:22:10+10:00 debug kernel[]: [   16.171811] ath: country maps to regdmn code: 0x3a
2017-05-30T16:22:10+10:00 debug kernel[]: [   16.171814] ath: Country alpha2 being used: US
2017-05-30T16:22:10+10:00 debug kernel[]: [   16.171817] ath: Regpair used: 0x3a
2017-05-30T16:22:10+10:00 info kernel[]: [   16.181560] Linux video capture interface: v2.00
2017-05-30T16:22:10+10:00 info kernel[]: [   16.192247] u32 classifier
2017-05-30T16:22:10+10:00 info kernel[]: [   16.194962]     input device check on
2017-05-30T16:22:10+10:00 info kernel[]: [   16.198630]     Actions configured
2017-05-30T16:22:10+10:00 info kernel[]: [   16.202559] Mirror/redirect action on
2017-05-30T16:22:10+10:00 info kernel[]: [   16.208205] GACT probability on
2017-05-30T16:22:10+10:00 info kernel[]: [   16.215982] netem: version 1.3
2017-05-30T16:22:10+10:00 info kernel[]: [   16.226437] nf_conntrack version 0.5.0 (16384 buckets, 65536 max)
2017-05-30T16:22:10+10:00 info kernel[]: [   16.237093] fuse init (API version 7.23)
2017-05-30T16:22:10+10:00 info kernel[]: [   16.252155] usbcore: registered new interface driver cdc_wdm
2017-05-30T16:22:10+10:00 info kernel[]: [   16.261037] Ebtables v2.0 registered
2017-05-30T16:22:10+10:00 info kernel[]: [   16.266043] ip_tables: (C) 2000-2006 Netfilter Core Team
2017-05-30T16:22:10+10:00 info kernel[]: [   16.474209] Netfilter messages via NETLINK v0.30.
2017-05-30T16:22:10+10:00 info kernel[]: [   16.479797] PPP MPPE Compression module registered
2017-05-30T16:22:10+10:00 info kernel[]: [   16.485164] NET: Registered protocol family 24
2017-05-30T16:22:10+10:00 info kernel[]: [   16.493222] usbcore: registered new interface driver ums-alauda
2017-05-30T16:22:10+10:00 info kernel[]: [   16.500047] usbcore: registered new interface driver ums-cypress
2017-05-30T16:22:10+10:00 info kernel[]: [   16.507036] usbcore: registered new interface driver ums-datafab
2017-05-30T16:22:10+10:00 info kernel[]: [   16.513895] usbcore: registered new interface driver ums-freecom
2017-05-30T16:22:10+10:00 info kernel[]: [   16.520835] usbcore: registered new interface driver ums-isd200
2017-05-30T06:22:10+10:00 err ntpdate[1910]: name server cannot be used: Try again (-3)
2017-05-30T16:22:10+10:00 info kernel[]: [   16.527753] usbcore: registered new interface driver ums-jumpshot
2017-05-30T16:22:10+10:00 info kernel[]: [   16.534708] usbcore: registered new interface driver ums-karma
2017-05-30T16:22:10+10:00 info kernel[]: [   16.541786] usbcore: registered new interface driver ums-sddr09
2017-05-30T16:22:10+10:00 info kernel[]: [   16.548632] usbcore: registered new interface driver ums-sddr55
2017-05-30T16:22:10+10:00 info kernel[]: [   16.555715] usbcore: registered new interface driver ums-usbat
2017-05-30T16:22:10+10:00 info kernel[]: [   16.567853] usbcore: registered new interface driver usbserial
2017-05-30T16:22:10+10:00 info kernel[]: [   16.573758] usbcore: registered new interface driver usbserial_generic
2017-05-30T16:22:10+10:00 info kernel[]: [   16.580327] usbserial: USB Serial support registered for generic
2017-05-30T16:22:10+10:00 info kernel[]: [   16.598222] xt_time: kernel timezone is -0000
2017-05-30T16:22:10+10:00 info kernel[]: [   16.616679] usbcore: registered new interface driver cdc_ether
2017-05-30T16:22:10+10:00 info kernel[]: [   16.627478] ctnetlink v0.93: registering with nfnetlink.
2017-05-30T16:22:10+10:00 info kernel[]: [   16.636706] usbcore: registered new interface driver qmi_wwan
2017-05-30T16:22:10+10:00 info kernel[]: [   16.643768] usbcore: registered new interface driver rndis_host
2017-05-30T16:22:10+10:00 info kernel[]: [   16.654891] usbcore: registered new interface driver uvcvideo
2017-05-30T16:22:10+10:00 info kernel[]: [   16.660683] USB Video Class driver (1.1.1)
2017-05-30T16:22:10+10:00 info kernel[]: [   16.670952] pci 0000:00:01.0: enabling device (0140 -> 0142)
2017-05-30T16:22:10+10:00 debug kernel[]: [   16.763379] ath: EEPROM regdomain: 0x0
2017-05-30T16:22:10+10:00 debug kernel[]: [   16.763383] ath: EEPROM indicates default country code should be used
2017-05-30T16:22:10+10:00 debug kernel[]: [   16.763386] ath: doing EEPROM country->regdmn map search
2017-05-30T16:22:10+10:00 debug kernel[]: [   16.763390] ath: country maps to regdmn code: 0x3a
2017-05-30T16:22:10+10:00 debug kernel[]: [   16.763393] ath: Country alpha2 being used: US
2017-05-30T16:22:10+10:00 debug kernel[]: [   16.763396] ath: Regpair used: 0x3a
2017-05-30T16:22:10+10:00 debug kernel[]: [   16.775237] ieee80211 phy1: Selected rate control algorithm 'minstrel_ht'
2017-05-30T16:22:10+10:00 info kernel[]: [   16.776645] ieee80211 phy1: Atheros AR9287 Rev:2 mem=0xf1d80000, irq=108
2017-05-30T16:22:10+10:00 info kernel[]: [   16.785120] usbcore: registered new interface driver option
2017-05-30T16:22:10+10:00 info kernel[]: [   16.790778] usbserial: USB Serial support registered for GSM modem (1-port)
2017-05-30T16:22:10+10:00 info kernel[]: [   16.798482] usbcore: registered new interface driver qcserial
2017-05-30T16:22:10+10:00 info kernel[]: [   16.804296] usbserial: USB Serial support registered for Qualcomm USB modem
2017-05-30T16:22:10+10:00 notice kernel[]: [   19.235703] random: nonblocking pool is initialized
2017-05-30T16:22:10+10:00 info kernel[]: [   25.101456] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
2017-05-30T16:22:10+10:00 info kernel[]: [   25.182276] IPv6: ADDRCONF(NETDEV_UP): eth1: link is not ready
2017-05-30T16:22:10+10:00 info kernel[]: [   25.185801] IPv6: ADDRCONF(NETDEV_UP): eth2: link is not ready
2017-05-30T16:22:10+10:00 info kernel[]: [   26.831153] device eth0 entered promiscuous mode
2017-05-30T16:22:10+10:00 info kernel[]: [   26.832169] IPv6: ADDRCONF(NETDEV_UP): br-lan: link is not ready
2017-05-30T16:22:10+10:00 info kernel[]: [   26.848804] device eth2 entered promiscuous mode
2017-05-30T16:22:10+10:00 info kernel[]: [   26.931989] IPv6: ADDRCONF(NETDEV_UP): eth1: link is not ready
2017-05-30T16:22:10+10:00 info kernel[]: [   27.101828] device br-lan entered promiscuous mode
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.291859] ath: EEPROM regdomain: 0x8024
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.291867] ath: EEPROM indicates we should expect a country code
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.291871] ath: doing EEPROM country->regdmn map search
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.291874] ath: country maps to regdmn code: 0x21
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.291877] ath: Country alpha2 being used: AU
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.291879] ath: Regpair used: 0x21
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.291883] ath: regdomain 0x8024 dynamically updated by user
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.291934] ath: EEPROM regdomain: 0x8024
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.291937] ath: EEPROM indicates we should expect a country code
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.291940] ath: doing EEPROM country->regdmn map search
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.291942] ath: country maps to regdmn code: 0x21
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.291945] ath: Country alpha2 being used: AU
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.291947] ath: Regpair used: 0x21
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.291949] ath: regdomain 0x8024 dynamically updated by user
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.295041] ath: EEPROM regdomain: 0x80cb
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.295047] ath: EEPROM indicates we should expect a country code
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.295050] ath: doing EEPROM country->regdmn map search
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.295053] ath: country maps to regdmn code: 0x36
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.295056] ath: Country alpha2 being used: CZ
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.295058] ath: Regpair used: 0x36
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.295062] ath: regdomain 0x80cb dynamically updated by user
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.295105] ath: EEPROM regdomain: 0x80cb
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.295108] ath: EEPROM indicates we should expect a country code
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.295111] ath: doing EEPROM country->regdmn map search
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.295113] ath: country maps to regdmn code: 0x36
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.295116] ath: Country alpha2 being used: CZ
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.295118] ath: Regpair used: 0x36
2017-05-30T16:22:10+10:00 debug kernel[]: [   27.295121] ath: regdomain 0x80cb dynamically updated by user
2017-05-30T16:22:10+10:00 info kernel[]: [   28.403542] IPv6: ADDRCONF(NETDEV_UP): wlan1: link is not ready
2017-05-30T16:22:10+10:00 info kernel[]: [   28.820598] mvneta f1030000.ethernet eth0: Link is Up - 1Gbps/Full - flow control off
2017-05-30T16:22:10+10:00 info kernel[]: [   28.840640] mvneta f1070000.ethernet eth2: Link is Up - 1Gbps/Full - flow control off
2017-05-30T16:22:10+10:00 info kernel[]: [   29.723393] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
2017-05-30T16:22:10+10:00 info kernel[]: [   29.723572] device wlan1 entered promiscuous mode
2017-05-30T16:22:10+10:00 info kernel[]: [   29.726381] br-lan: port 1(eth0) entered forwarding state
2017-05-30T16:22:10+10:00 info kernel[]: [   29.726404] br-lan: port 1(eth0) entered forwarding state
2017-05-30T16:22:10+10:00 info kernel[]: [   29.726444] br-lan: port 2(eth2) entered forwarding state
2017-05-30T16:22:10+10:00 info kernel[]: [   29.726455] br-lan: port 2(eth2) entered forwarding state
2017-05-30T16:22:10+10:00 info kernel[]: [   29.726955] IPv6: ADDRCONF(NETDEV_CHANGE): br-lan: link becomes ready
2017-05-30T16:22:10+10:00 info kernel[]: [   29.728018] device wlan0 entered promiscuous mode
2017-05-30T16:22:10+10:00 debug kernel[]: [   29.728210] ath: EEPROM regdomain: 0x8024
2017-05-30T16:22:10+10:00 debug kernel[]: [   29.728214] ath: EEPROM indicates we should expect a country code
2017-05-30T16:22:10+10:00 debug kernel[]: [   29.728217] ath: doing EEPROM country->regdmn map search
2017-05-30T16:22:10+10:00 debug kernel[]: [   29.728220] ath: country maps to regdmn code: 0x21
2017-05-30T16:22:10+10:00 debug kernel[]: [   29.728223] ath: Country alpha2 being used: AU
2017-05-30T16:22:10+10:00 debug kernel[]: [   29.728226] ath: Regpair used: 0x21
2017-05-30T16:22:10+10:00 debug kernel[]: [   29.728229] ath: regdomain 0x8024 dynamically updated by user
2017-05-30T16:22:10+10:00 debug kernel[]: [   29.728273] ath: EEPROM regdomain: 0x8024
2017-05-30T16:22:10+10:00 debug kernel[]: [   29.728275] ath: EEPROM indicates we should expect a country code
2017-05-30T16:22:10+10:00 debug kernel[]: [   29.728278] ath: doing EEPROM country->regdmn map search
2017-05-30T16:22:10+10:00 debug kernel[]: [   29.728280] ath: country maps to regdmn code: 0x21
2017-05-30T16:22:10+10:00 debug kernel[]: [   29.728283] ath: Country alpha2 being used: AU
2017-05-30T16:22:10+10:00 debug kernel[]: [   29.728285] ath: Regpair used: 0x21
2017-05-30T16:22:10+10:00 debug kernel[]: [   29.728288] ath: regdomain 0x8024 dynamically updated by user
2017-05-30T16:22:10+10:00 info kernel[]: [   29.788162] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
2017-05-30T16:22:10+10:00 info kernel[]: [   29.788223] br-lan: port 3(wlan1) entered forwarding state
2017-05-30T16:22:10+10:00 info kernel[]: [   29.788242] br-lan: port 3(wlan1) entered forwarding state
2017-05-30T16:22:10+10:00 info kernel[]: [   29.796082] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
2017-05-30T16:22:10+10:00 info kernel[]: [   29.796127] br-lan: port 4(wlan0) entered forwarding state
2017-05-30T16:22:10+10:00 info kernel[]: [   29.796144] br-lan: port 4(wlan0) entered forwarding state
2017-05-30T16:22:10+10:00 info kernel[]: [   30.931012] mvneta f1034000.ethernet eth1: Link is Up - 1Gbps/Full - flow control off
2017-05-30T16:22:10+10:00 info kernel[]: [   30.931033] IPv6: ADDRCONF(NETDEV_CHANGE): eth1: link becomes ready
2017-05-30T16:22:10+10:00 info kernel[]: [   31.720581] br-lan: port 2(eth2) entered forwarding state
2017-05-30T16:22:10+10:00 info kernel[]: [   31.720613] br-lan: port 1(eth0) entered forwarding state
2017-05-30T16:22:10+10:00 info kernel[]: [   31.780586] br-lan: port 3(wlan1) entered forwarding state
2017-05-30T16:22:10+10:00 info kernel[]: [   31.790582] br-lan: port 4(wlan0) entered forwarding state
2017-05-30T06:22:10+10:00 notice netifd[]: Network device 'wlan0' link is up
2017-05-30T06:22:10+10:00 notice netifd[]: Network device 'wlan1' link is up
2017-05-30T06:22:10+10:00 warning odhcpd[1733]: DHCPV6 SOLICIT IA_NA from 000100011e015dabb4ae2b2d8d5d on br-lan: ok fd55:c3f2:2a6::783/128 
2017-05-30T16:22:10+10:00 err dnsmasq-dhcp[2056]: bad line at /etc/ethers line 1
2017-05-30T16:22:10+10:00 err dnsmasq-dhcp[2056]: bad line at /etc/ethers line 2
2017-05-30T16:22:10+10:00 err dnsmasq-dhcp[2056]: bad line at /etc/ethers line 3
2017-05-30T16:22:10+10:00 info dnsmasq-dhcp[2056]: read /etc/ethers - 0 addresses
2017-05-30T06:22:10+10:00 warning odhcpd[1733]: DHCPV6 CONFIRM IA_NA from 00046836d59efa382760f3193e5ec5bf4a24 on br-lan: not on-link 
2017-05-30T06:22:10+10:00 warning odhcpd[1733]: DHCPV6 SOLICIT IA_NA from 00046836d59efa382760f3193e5ec5bf4a24 on br-lan: ok fd55:c3f2:2a6::33f/128 
2017-05-30T16:22:11+10:00 info dnsmasq-dhcp[2056]: DHCPDISCOVER(br-lan) 169.254.100.100 00:08:9b:d9:b9:5a 
2017-05-30T16:22:11+10:00 info dnsmasq-dhcp[2056]: DHCPOFFER(br-lan) 192.168.0.13 00:08:9b:d9:b9:5a 
2017-05-30T16:22:11+10:00 info dnsmasq-dhcp[2056]: DHCPREQUEST(br-lan) 192.168.0.13 00:08:9b:d9:b9:5a 
2017-05-30T16:22:11+10:00 info dnsmasq-dhcp[2056]: DHCPACK(br-lan) 192.168.0.13 00:08:9b:d9:b9:5a Nessie
2017-05-30T06:22:11+10:00 warning odhcpd[1733]: DHCPV6 REQUEST IA_NA from 000100011e015dabb4ae2b2d8d5d on br-lan: ok fd55:c3f2:2a6::783/128 
2017-05-30T16:22:11+10:00 err dnsmasq-dhcp[2056]: bad line at /etc/ethers line 1
2017-05-30T16:22:11+10:00 err dnsmasq-dhcp[2056]: bad line at /etc/ethers line 2
2017-05-30T16:22:11+10:00 err dnsmasq-dhcp[2056]: bad line at /etc/ethers line 3
2017-05-30T16:22:11+10:00 info dnsmasq-dhcp[2056]: read /etc/ethers - 0 addresses
2017-05-30T06:22:11+10:00 warning odhcpd[1733]: DHCPV6 REQUEST IA_NA from 00046836d59efa382760f3193e5ec5bf4a24 on br-lan: ok fd55:c3f2:2a6::33f/128 
2017-05-30T16:22:12+10:00 info dnsmasq-dhcp[2056]: DHCPDISCOVER(br-lan) 192.168.0.12 b8:ae:ed:72:f8:8d 
2017-05-30T16:22:12+10:00 info dnsmasq-dhcp[2056]: DHCPOFFER(br-lan) 192.168.0.12 b8:ae:ed:72:f8:8d 
2017-05-30T16:22:12+10:00 info dnsmasq-dhcp[2056]: DHCPREQUEST(br-lan) 192.168.0.12 b8:ae:ed:72:f8:8d 
2017-05-30T16:22:12+10:00 info dnsmasq-dhcp[2056]: DHCPACK(br-lan) 192.168.0.12 b8:ae:ed:72:f8:8d Cyclops
2017-05-30T06:22:15+10:00 err ntpdate[2235]: name server cannot be used: Try again (-3)
2017-05-30T16:22:18+10:00 info dnsmasq-dhcp[2056]: DHCPDISCOVER(br-lan) b4:ae:2b:2d:8d:5d 
2017-05-30T16:22:18+10:00 info dnsmasq-dhcp[2056]: DHCPOFFER(br-lan) 192.168.0.54 b4:ae:2b:2d:8d:5d 
2017-05-30T16:22:18+10:00 info dnsmasq-dhcp[2056]: DHCPREQUEST(br-lan) 192.168.0.54 b4:ae:2b:2d:8d:5d 
2017-05-30T16:22:18+10:00 info dnsmasq-dhcp[2056]: DHCPACK(br-lan) 192.168.0.54 b4:ae:2b:2d:8d:5d Dani-Surface
2017-05-30T06:22:20+10:00 err ntpdate[2332]: name server cannot be used: Try again (-3)
2017-05-30T06:22:20+10:00 info pppd[2354]: Plugin rp-pppoe.so loaded.
2017-05-30T06:22:20+10:00 info pppd[2354]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
2017-05-30T06:22:20+10:00 emerg sfpswitch.py[1555]: Called /etc/init.d/kresd start
2017-05-30T06:22:20+10:00 notice pppd[2354]: pppd 2.4.7 started by root, uid 0
2017-05-30T06:22:20+10:00 info pppd[2354]: PPP session is 1664
2017-05-30T06:22:20+10:00 warning pppd[2354]: Connected to 3c:08:f6:07:06:10 via interface eth1
2017-05-30T16:22:20+10:00 info kernel[]: [   42.379339] pppoe-wan: renamed from ppp0
2017-05-30T06:22:20+10:00 info pppd[2354]: Using interface pppoe-wan
2017-05-30T06:22:20+10:00 notice pppd[2354]: Connect: pppoe-wan <--> eth1
2017-05-30T06:22:20+10:00 notice pppd[2354]: PAP authentication succeeded
2017-05-30T06:22:20+10:00 notice pppd[2354]: peer from calling number 3C:08:F6:07:06:10 authorized
2017-05-30T06:22:20+10:00 notice pppd[2354]: local  IP address 61.68.218.247
2017-05-30T06:22:20+10:00 notice pppd[2354]: remote IP address 10.20.22.139
2017-05-30T06:22:20+10:00 notice pppd[2354]: primary   DNS address 203.12.160.35
2017-05-30T06:22:20+10:00 notice pppd[2354]: secondary DNS address 203.12.160.36
2017-05-30T06:22:20+10:00 notice netifd[]: Network device 'pppoe-wan' link is up
2017-05-30T06:22:20+10:00 notice netifd[]: Interface 'wan6' is enabled
2017-05-30T06:22:20+10:00 notice netifd[]: Network alias 'pppoe-wan' link is up
2017-05-30T06:22:20+10:00 notice netifd[]: Interface 'wan6' has link connectivity 
2017-05-30T06:22:20+10:00 notice netifd[]: Interface 'wan6' is setting up now
2017-05-30T06:22:20+10:00 notice netifd[]: Interface 'wan' is now up
2017-05-30T06:22:20+10:00 notice firewall[]: Reloading firewall due to ifup of wan (pppoe-wan)
2017-05-30T16:22:20+10:00 info dnsmasq[2056]: exiting on receipt of SIGTERM
2017-05-30T16:22:20+10:00 info dnsmasq[2489]: started, version 2.73 DNS disabled
2017-05-30T16:22:20+10:00 info dnsmasq[2489]: compile time options: IPv6 GNU-getopt no-DBus no-i18n no-IDN DHCP no-DHCPv6 no-Lua TFTP no-conntrack no-ipset no-auth no-DNSSEC loop-detect inotify
2017-05-30T16:22:20+10:00 info dnsmasq[2489]: DNS service limited to local subnets
2017-05-30T16:22:20+10:00 info dnsmasq-dhcp[2489]: DHCP, IP range 192.168.0.101 -- 192.168.0.250, lease time 12h
2017-05-30T16:22:20+10:00 err dnsmasq-dhcp[2489]: bad line at /etc/ethers line 1
2017-05-30T16:22:20+10:00 err dnsmasq-dhcp[2489]: bad line at /etc/ethers line 2
2017-05-30T16:22:20+10:00 err dnsmasq-dhcp[2489]: bad line at /etc/ethers line 3
2017-05-30T16:22:20+10:00 info dnsmasq-dhcp[2489]: read /etc/ethers - 0 addresses
2017-05-30T06:22:21+10:00 crit mountd[2593]: Starting OpenWrt (auto)mountd V1
2017-05-30T06:22:21+10:00 crit mountd[2593]: trying to mount /tmp/run/mountd/ as the autofs root
2017-05-30T06:22:21+10:00 debug updater[2611]: src/lib/locks.c:44 (lua_acquire): Trying to get a lock at //var/lock/opkg.lock
2017-05-30T06:22:21+10:00 debug updater[2611]: backend.lua:353 (status_parse): Parsing status file /usr/lib/opkg/status
2017-05-30T06:22:21+10:00 debug updater[2611]: src/lib/journal.c:123 (journal_open): Opening journal
2017-05-30T06:22:21+10:00 info updater[2611]: transaction.lua:354 (recover): No journal to recover
2017-05-30T06:22:21+10:00 emerg sfpswitch.py[1555]: e[34mINFOe[0m:No journal to recover
2017-05-30T06:22:21+10:00 warning updater[2611]: src/lib/locks.c:87 (lua_lock_gc): Lock on //var/lock/opkg.lock released by garbage collector
2017-05-30T06:22:21+10:00 emerg sfpswitch.py[1555]: e[35mWARNe[0m:Lock on //var/lock/opkg.lock released by garbage collector
2017-05-30T06:22:22+10:00 notice ddns-scripts[2653]: wechner_info: PID '2653' started at 2017-05-30 16:22
2017-05-30T06:22:22+10:00 notice ddns-scripts[2654]: hitch_hiking_info: PID '2654' started at 2017-05-30 16:22
2017-05-30T06:22:22+10:00 notice ddns-scripts[2655]: thumbs_place: PID '2655' started at 2017-05-30 16:22
2017-05-30T06:22:22+10:00 notice ddns-scripts[2656]: ivkovic_info: PID '2656' started at 2017-05-30 16:22
2017-05-30T06:22:22+10:00 notice ddns-scripts[2658]: polacheck_info: PID '2658' started at 2017-05-30 16:22
2017-05-30T06:22:22+10:00 notice ddns-scripts[2659]: leaderboard_space: PID '2659' started at 2017-05-30 16:22
2017-05-30T06:22:22+10:00 notice ddns-scripts[2657]: kovener_info: PID '2657' started at 2017-05-30 16:22
2017-05-30T06:22:22+10:00 emerg sfpswitch.py[1555]:   % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
2017-05-30T06:22:22+10:00 emerg sfpswitch.py[1555]:                                  Dload  Upload   Total   Spent    Left  Speed
2017-05-30T06:22:23+10:00 info sshd[3565]: Accepted publickey for root from 192.168.0.11 port 59666 ssh2: RSA SHA256:PK0uUqcUhwWdfEiR/3qh6xVE+FoECBleVGf9gYUE+aE
2017-05-30T06:22:23+10:00 emerg sfpswitch.py[1555]: 
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
  0     0    0     0    0     0      0      0 --:--:--  0:00:01 --:--:--     0
100  1080  100  1080    0     0    647      0  0:00:01  0:00:01 --:--:--   798
2017-05-30T06:22:24+10:00 warning []: Unable to use //tmp//yin2yang.xsl (No such file or directory).
2017-05-30T06:22:24+10:00 warning []: YANG format data models will not be available via get-schema.
2017-05-30T06:22:24+10:00 warning []: Unable to get tty (Not a tty) to get the client's hostname (session 3786).
2017-05-30T06:22:30+10:00 info pppd[3819]: Plugin rp-pppoe.so loaded.
2017-05-30T06:22:30+10:00 info pppd[3819]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.7
2017-05-30T06:22:30+10:00 err pppd[3819]: unrecognized option 'nic-pppoe-wan'
2017-05-30T06:22:30+10:00 notice netifd[]: wan6 (3819): /usr/sbin/pppd: unrecognized option 'nic-pppoe-wan'
2017-05-30T06:22:30+10:00 notice netifd[]: wan6 (3819): pppd version 2.4.7
2017-05-30T06:22:30+10:00 notice netifd[]: wan6 (3819): Usage: /usr/sbin/pppd [ options ], where options are:
2017-05-30T06:22:30+10:00 notice netifd[]: wan6 (3819): 	<device>	Communicate over the named device
2017-05-30T06:22:30+10:00 notice netifd[]: wan6 (3819): 	<speed>		Set the baud rate to <speed>
2017-05-30T06:22:30+10:00 notice netifd[]: wan6 (3819): 	<loc>:<rem>	Set the local and/or remote interface IP
2017-05-30T06:22:30+10:00 notice netifd[]: wan6 (3819): 			addresses.  Either one may be omitted.
2017-05-30T06:22:30+10:00 notice netifd[]: wan6 (3819): 	asyncmap <n>	Set the desired async map to hex <n>
2017-05-30T06:22:30+10:00 notice netifd[]: wan6 (3819): 	auth		Require authentication from peer
2017-05-30T06:22:30+10:00 notice netifd[]: wan6 (3819):         connect <p>     Invoke shell command <p> to set up the serial line
2017-05-30T06:22:30+10:00 notice netifd[]: wan6 (3819): 	crtscts		Use hardware RTS/CTS flow control
2017-05-30T06:22:30+10:00 notice netifd[]: wan6 (3819): 	defaultroute	Add default route through interface
2017-05-30T06:22:30+10:00 notice netifd[]: wan6 (3819): 	file <f>	Take options from file <f>
2017-05-30T06:22:30+10:00 notice netifd[]: wan6 (3819): 	modem		Use modem control lines
2017-05-30T06:22:30+10:00 notice netifd[]: wan6 (3819): 	mru <n>		Set MRU value to <n> for negotiation
2017-05-30T06:22:30+10:00 notice netifd[]: wan6 (3819): See pppd(8) for more options.
2017-05-30T06:22:30+10:00 notice netifd[]: Interface 'wan6' is now down
2017-05-30T06:22:30+10:00 notice netifd[]: Interface 'wan6' is disabled
2017-05-30T06:22:30+10:00 info kresd[2556]: [ ta ] key: 19036 state: Valid
2017-05-30T06:22:30+10:00 info kresd[2556]: [ ta ] next refresh for . in 22.360138888889 hours
2017-05-30T06:22:31+10:00 warning updater[3677]: requests.lua:335 (func): Script revision-specific not found, but ignoring its absence as requested
2017-05-30T06:22:31+10:00 emerg kresd[2556]: e[35mWARNe[0m:Script revision-specific not found, but ignoring its absence as requested
2017-05-30T06:22:35+10:00 warning updater[3677]: requests.lua:335 (func): Script serial-specific not found, but ignoring its absence as requested
2017-05-30T06:22:35+10:00 emerg kresd[2556]: e[35mWARNe[0m:Script serial-specific not found, but ignoring its absence as requested
2017-05-30T06:22:40+10:00 info hostapd[]: wlan1: STA 00:28:f8:33:94:ec IEEE 802.11: authenticated
2017-05-30T06:22:40+10:00 info hostapd[]: wlan1: STA 00:28:f8:33:94:ec IEEE 802.11: associated (aid 1)
2017-05-30T06:22:40+10:00 info hostapd[]: wlan1: STA 00:28:f8:33:94:ec RADIUS: starting accounting session 71F84AF03E4DEC8C
2017-05-30T06:22:40+10:00 info hostapd[]: wlan1: STA 00:28:f8:33:94:ec WPA: pairwise key handshake completed (RSN)
2017-05-30T16:22:40+10:00 info dnsmasq-dhcp[2489]: DHCPREQUEST(br-lan) 192.168.0.52 00:28:f8:33:94:ec 
2017-05-30T16:22:40+10:00 info dnsmasq-dhcp[2489]: DHCPACK(br-lan) 192.168.0.52 00:28:f8:33:94:ec Dani-Spectre
2017-05-30T06:22:41+10:00 warning odhcpd[1733]: DHCPV6 SOLICIT IA_NA from 00010001205085c400e04d680074 on br-lan: ok fd55:c3f2:2a6::59d/128 
2017-05-30T16:22:42+10:00 warning odhcpd[]: Last message 'DHCPV6 SOLICIT IA_NA' repeated 1 times, supressed by syslog-ng on Cerberus
2017-05-30T06:22:42+10:00 warning odhcpd[1733]: DHCPV6 REQUEST IA_NA from 00010001205085c400e04d680074 on br-lan: ok fd55:c3f2:2a6::59d/128 
2017-05-30T16:22:42+10:00 err dnsmasq-dhcp[2489]: bad line at /etc/ethers line 1
2017-05-30T16:22:42+10:00 err dnsmasq-dhcp[2489]: bad line at /etc/ethers line 2
2017-05-30T16:22:42+10:00 err dnsmasq-dhcp[2489]: bad line at /etc/ethers line 3
2017-05-30T16:22:42+10:00 info dnsmasq-dhcp[2489]: read /etc/ethers - 0 addresses
2017-05-30T06:23:35+10:00 warning updater[3677]: src/lib/locks.c:87 (lua_lock_gc): Lock on //var/lock/opkg.lock released by garbage collector
2017-05-30T06:23:35+10:00 emerg kresd[2556]: e[35mWARNe[0m:Lock on //var/lock/opkg.lock released by garbage collector
2017-05-30T06:23:37+10:00 info smartd[5721]: smartd 6.5 2016-05-07 r4318 [armv7l-linux-4.4.59-627f0117679bc72ef5e58881035f567a-4] (localbuild)
2017-05-30T06:23:37+10:00 info smartd[5721]: Copyright (C) 2002-16, Bruce Allen, Christian Franke, www.smartmontools.org
2017-05-30T06:23:37+10:00 info smartd[5721]: Opened configuration file /etc/smartd.conf
2017-05-30T06:23:37+10:00 info smartd[5721]: Configuration file /etc/smartd.conf parsed.
2017-05-30T06:23:37+10:00 info smartd[5721]: Device: /dev/hdb, open() failed: No such device
2017-05-30T06:23:37+10:00 info smartd[5721]: Monitoring 0 ATA/SATA, 0 SCSI/SAS and 0 NVMe devices
2017-05-30T06:23:37+10:00 info smartd[5723]: smartd has fork()ed into background mode. New PID=5723.
2017-05-30T06:23:40+10:00 emerg kresd[2556]: setting up led Auto-configuration for PCI1
2017-05-30T06:23:40+10:00 emerg kresd[2556]: setting up led Auto-configuration for PCI2
2017-05-30T06:23:40+10:00 emerg kresd[2556]: setting up led Auto-configuration for PCI3
2017-05-30T06:23:41+10:00 emerg turris[]: Router Turris successfully started.
2017-05-30T06:23:41+10:00 info procd[]: - init complete -
2017-05-30T06:24:02+10:00 info /usr/sbin/cron[6467]: (root) CMD (nethist_stats.lua)
2017-05-30T06:24:02+10:00 info /usr/sbin/cron[6468]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:25:01+10:00 info /usr/sbin/cron[8062]: (root) CMD (majordomo_db.sh downsize)
2017-05-30T06:25:01+10:00 info /usr/sbin/cron[8063]: (root) CMD (   /usr/bin/notifier)
2017-05-30T06:25:01+10:00 info /usr/sbin/cron[8058]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:25:01+10:00 info /usr/sbin/cron[8061]: (root) CMD (/usr/bin/watchdog.sh)
2017-05-30T06:26:01+10:00 info /usr/sbin/cron[9872]: (root) CMD (nethist_stats.lua)
2017-05-30T06:26:01+10:00 info /usr/sbin/cron[9873]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T16:26:34+10:00 info dnsmasq-dhcp[2489]: DHCPINFORM(br-lan) 192.168.0.55 c4:85:08:60:fd:2e 
2017-05-30T16:26:34+10:00 info dnsmasq-dhcp[2489]: DHCPACK(br-lan) 192.168.0.55 c4:85:08:60:fd:2e Julie-Laptop
2017-05-30T06:26:42+10:00 warning odhcpd[1733]: DHCPV6 SOLICIT IA_NA from 0001000119d0a4fce8039adc62ad on br-lan: ok fd55:c3f2:2a6::a34/128 
2017-05-30T06:26:43+10:00 warning odhcpd[1733]: DHCPV6 REQUEST IA_NA from 0001000119d0a4fce8039adc62ad on br-lan: ok fd55:c3f2:2a6::a34/128 
2017-05-30T16:26:43+10:00 err dnsmasq-dhcp[2489]: bad line at /etc/ethers line 1
2017-05-30T16:26:43+10:00 err dnsmasq-dhcp[2489]: bad line at /etc/ethers line 2
2017-05-30T16:26:43+10:00 err dnsmasq-dhcp[2489]: bad line at /etc/ethers line 3
2017-05-30T16:26:43+10:00 info dnsmasq-dhcp[2489]: read /etc/ethers - 0 addresses
2017-05-30T06:27:01+10:00 info /usr/sbin/cron[11565]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:27:32+10:00 info hostapd[]: wlan1: STA 3c:ab:8e:40:94:b3 IEEE 802.11: authenticated
2017-05-30T06:27:32+10:00 info hostapd[]: wlan1: STA 3c:ab:8e:40:94:b3 IEEE 802.11: associated (aid 2)
2017-05-30T06:27:32+10:00 info hostapd[]: wlan1: STA 3c:ab:8e:40:94:b3 RADIUS: starting accounting session 52B6BA49BEC18A28
2017-05-30T06:27:32+10:00 info hostapd[]: wlan1: STA 3c:ab:8e:40:94:b3 WPA: pairwise key handshake completed (RSN)
2017-05-30T16:27:34+10:00 info dnsmasq-dhcp[2489]: DHCPDISCOVER(br-lan) 3c:ab:8e:40:94:b3 
2017-05-30T16:27:34+10:00 info dnsmasq-dhcp[2489]: DHCPOFFER(br-lan) 192.168.0.49 3c:ab:8e:40:94:b3 
2017-05-30T16:27:35+10:00 info dnsmasq-dhcp[2489]: DHCPREQUEST(br-lan) 192.168.0.49 3c:ab:8e:40:94:b3 
2017-05-30T16:27:35+10:00 info dnsmasq-dhcp[2489]: DHCPACK(br-lan) 192.168.0.49 3c:ab:8e:40:94:b3 Tablet-Dani-iPad
2017-05-30T06:27:35+10:00 info hostapd[]: wlan1: STA 3c:ab:8e:40:94:b3 IEEE 802.11: disassociated
2017-05-30T06:27:36+10:00 info hostapd[]: wlan1: STA 3c:ab:8e:40:94:b3 IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)
2017-05-30T06:27:49+10:00 info hostapd[]: wlan1: STA 3c:ab:8e:40:94:b3 IEEE 802.11: authenticated
2017-05-30T06:27:49+10:00 info hostapd[]: wlan1: STA 3c:ab:8e:40:94:b3 IEEE 802.11: associated (aid 2)
2017-05-30T06:27:49+10:00 info hostapd[]: wlan1: STA 3c:ab:8e:40:94:b3 RADIUS: starting accounting session C6C8D460E7593789
2017-05-30T06:27:49+10:00 info hostapd[]: wlan1: STA 3c:ab:8e:40:94:b3 WPA: pairwise key handshake completed (RSN)
2017-05-30T16:27:49+10:00 info dnsmasq-dhcp[2489]: DHCPDISCOVER(br-lan) 3c:ab:8e:40:94:b3 
2017-05-30T16:27:49+10:00 info dnsmasq-dhcp[2489]: DHCPOFFER(br-lan) 192.168.0.49 3c:ab:8e:40:94:b3 
2017-05-30T16:27:50+10:00 info dnsmasq-dhcp[2489]: DHCPREQUEST(br-lan) 192.168.0.49 3c:ab:8e:40:94:b3 
2017-05-30T16:27:50+10:00 info dnsmasq-dhcp[2489]: DHCPACK(br-lan) 192.168.0.49 3c:ab:8e:40:94:b3 Tablet-Dani-iPad
2017-05-30T06:28:01+10:00 info /usr/sbin/cron[13224]: (root) CMD (nethist_stats.lua)
2017-05-30T06:28:01+10:00 info /usr/sbin/cron[13225]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:28:44+10:00 warning odhcpd[1733]: DHCPV6 REBIND IA_NA from 00010001207e2efdb827eb24db8b on br-lan: ok 
2017-05-30T06:29:01+10:00 info /usr/sbin/cron[14914]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:30:01+10:00 info /usr/sbin/cron[16579]: (root) CMD (   /usr/bin/notifier)
2017-05-30T06:30:01+10:00 info /usr/sbin/cron[16575]: (root) CMD (/usr/bin/get-api-crl)
2017-05-30T06:30:01+10:00 info /usr/sbin/cron[16582]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:30:01+10:00 info /usr/sbin/cron[16583]: (root) CMD (majordomo_db.sh downsize)
2017-05-30T06:30:01+10:00 info /usr/sbin/cron[16585]: (root) CMD (nethist_stats.lua)
2017-05-30T06:30:01+10:00 info /usr/sbin/cron[16584]: (root) CMD (/usr/bin/watchdog.sh)
2017-05-30T06:30:03+10:00 warning watchdog[]: Restarted nethist
2017-05-30T06:31:01+10:00 info /usr/sbin/cron[18279]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:32:01+10:00 info /usr/sbin/cron[19994]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:32:01+10:00 info /usr/sbin/cron[19995]: (root) CMD (nethist_stats.lua)
2017-05-30T06:32:09+10:00 info hostapd[]: wlan1: STA 3c:ab:8e:40:94:b3 WPA: group key handshake completed (RSN)
2017-05-30T06:33:01+10:00 info /usr/sbin/cron[21951]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:34:01+10:00 info /usr/sbin/cron[23611]: (root) CMD (nethist_stats.lua)
2017-05-30T06:34:01+10:00 info /usr/sbin/cron[23610]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:35:01+10:00 info /usr/sbin/cron[25307]: (root) CMD (   /usr/bin/notifier)
2017-05-30T06:35:01+10:00 info /usr/sbin/cron[25306]: (root) CMD (/usr/bin/watchdog.sh)
2017-05-30T06:35:01+10:00 info /usr/sbin/cron[25308]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:35:01+10:00 info /usr/sbin/cron[25312]: (root) CMD (majordomo_db.sh downsize)
2017-05-30T06:36:01+10:00 info /usr/sbin/cron[26952]: (root) CMD (nethist_stats.lua)
2017-05-30T06:36:01+10:00 info /usr/sbin/cron[26953]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:37:01+10:00 info /usr/sbin/cron[28647]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:38:01+10:00 info /usr/sbin/cron[30313]: (root) CMD (nethist_stats.lua)
2017-05-30T06:38:01+10:00 info /usr/sbin/cron[30314]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:39:01+10:00 info /usr/sbin/cron[31974]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:39:38+10:00 warning odhcpd[1733]: DHCPV6 REBIND IA_NA from 00010001207e2efdb827eb24db8b on br-lan: ok 
2017-05-30T06:40:01+10:00 info /usr/sbin/cron[1264]: (root) CMD (   /usr/bin/notifier)
2017-05-30T06:40:01+10:00 info /usr/sbin/cron[1267]: (root) CMD (nethist_stats.lua)
2017-05-30T06:40:01+10:00 info /usr/sbin/cron[1265]: (root) CMD (/usr/bin/watchdog.sh)
2017-05-30T06:40:01+10:00 info /usr/sbin/cron[1269]: (root) CMD (majordomo_db.sh downsize)
2017-05-30T06:40:01+10:00 info /usr/sbin/cron[1268]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:40:02+10:00 warning watchdog[]: Restarted nethist
2017-05-30T06:41:01+10:00 info /usr/sbin/cron[3140]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:42:01+10:00 info /usr/sbin/cron[4841]: (root) CMD (nethist_stats.lua)
2017-05-30T06:42:01+10:00 info /usr/sbin/cron[4840]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:42:09+10:00 info hostapd[]: wlan1: STA 3c:ab:8e:40:94:b3 WPA: group key handshake completed (RSN)
2017-05-30T16:42:24+10:00 info kernel[]: [ 1244.843920] nf_conntrack: automatic helper assignment is deprecated and it will be removed soon. Use the iptables CT target to attach helpers instead.
2017-05-30T06:43:01+10:00 info /usr/sbin/cron[6766]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:44:01+10:00 info /usr/sbin/cron[8458]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:44:01+10:00 info /usr/sbin/cron[8457]: (root) CMD (nethist_stats.lua)
2017-05-30T06:45:01+10:00 info /usr/sbin/cron[10938]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:45:01+10:00 info /usr/sbin/cron[10936]: (root) CMD (/usr/bin/watchdog.sh)
2017-05-30T06:45:01+10:00 info /usr/sbin/cron[10934]: (root) CMD (   /usr/bin/notifier)
2017-05-30T06:45:01+10:00 info /usr/sbin/cron[10937]: (root) CMD (majordomo_db.sh downsize)
2017-05-30T06:46:01+10:00 info /usr/sbin/cron[12978]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:46:01+10:00 info /usr/sbin/cron[12979]: (root) CMD (nethist_stats.lua)
2017-05-30T06:47:01+10:00 info /usr/sbin/cron[15057]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:48:01+10:00 info /usr/sbin/cron[17120]: (root) CMD (nethist_stats.lua)
2017-05-30T06:48:01+10:00 info /usr/sbin/cron[17122]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:48:42+10:00 warning odhcpd[1733]: DHCPV6 REBIND IA_NA from 00010001207e2efdb827eb24db8b on br-lan: ok 
2017-05-30T06:49:01+10:00 info /usr/sbin/cron[19212]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:50:01+10:00 info /usr/sbin/cron[21291]: (root) CMD (   /usr/bin/notifier)
2017-05-30T06:50:01+10:00 info /usr/sbin/cron[21294]: (root) CMD (/usr/bin/watchdog.sh)
2017-05-30T06:50:01+10:00 info /usr/sbin/cron[21295]: (root) CMD (majordomo_db.sh downsize)
2017-05-30T06:50:01+10:00 info /usr/sbin/cron[21301]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:50:01+10:00 info /usr/sbin/cron[21299]: (root) CMD (nethist_stats.lua)
2017-05-30T06:50:03+10:00 warning watchdog[]: Restarted nethist
2017-05-30T06:51:01+10:00 info /usr/sbin/cron[23347]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:52:01+10:00 info /usr/sbin/cron[25421]: (root) CMD (nethist_stats.lua)
2017-05-30T06:52:01+10:00 info /usr/sbin/cron[25422]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:52:09+10:00 info hostapd[]: wlan1: STA 3c:ab:8e:40:94:b3 WPA: group key handshake completed (RSN)
2017-05-30T06:53:01+10:00 info /usr/sbin/cron[27748]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:54:01+10:00 info /usr/sbin/cron[29778]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:54:01+10:00 info /usr/sbin/cron[29779]: (root) CMD (nethist_stats.lua)
2017-05-30T06:54:45+10:00 info sshd[31255]: Connection closed by 192.168.0.11 port 38992 [preauth]
2017-05-30T06:54:48+10:00 info sshd[31439]: Connection closed by 192.168.0.11 port 39166 [preauth]
2017-05-30T06:55:01+10:00 info /usr/sbin/cron[31905]: (root) CMD (/usr/bin/watchdog.sh)
2017-05-30T06:55:01+10:00 info /usr/sbin/cron[31907]: (root) CMD (/usr/bin/rainbow_button_sync.sh)
2017-05-30T06:55:01+10:00 info /usr/sbin/cron[31908]: (root) CMD (majordomo_db.sh downsize)
2017-05-30T06:55:01+10:00 info /usr/sbin/cron[31919]: (root) CMD (   /usr/bin/notifier)

Hi, I seem to have this issue too. Is there any known workaround? Is the bug logged and tracked? If so where? Thanks

There is another topic related to this one: see “Time difference is System Log”

Will this be fixed any time soon as it is still happening with

Turris OS 3.9.6
Kernel 4.4.119-082ea0f4a4e204b99821bedcb349ed54-0

I would make a pull request for a fix , unfortunatelly I dont know, where are settings of syslog-ng.conf stored / created within https://github.com/CZ-NIC/turris-os

EDIT: https://github.com/CZ-NIC/turris-os-packages/pull/48

2 Likes