Syslog time issues

[Marko Polo]

Hi there,
I have a weird time inconsistency which apps write to standard log. For example, transmission writes some false time, which doesn't correspond to system one:

Jul 28 16:47:27 host dropbear[26782]: Child connection from XXXXXXXXXXXXXX
Jul 28 16:47:28 host dropbear[26782]: Pubkey auth succeeded for 'Polo' with key sha1!!
Jul 28 13:47:50 host transmission-daemon[1997]: El Elegido (2016) 1080p Could not connect to tracker (announcer.c:995)
Jul 28 13:47:50 host transmission-daemon[1997]: El Elegido (2016) 1080p Retrying announce in 7205 seconds. (announcer.c:1004)
Jul 28 13:48:03 host transmission-daemon[1997]: The Homesman 2014 720p Bluray DTS x264 Worldwide7477 Could not connect to tracker (announcer.c:995)
Jul 28 13:48:03 host transmission-daemon[1997]: The Homesman 2014 720p Bluray DTS x264 Worldwide7477 Retrying announce in 7200 seconds. (announcer.c:1004)

It is obviously wrong that 13.47 goes after 16.47. Where Transmission takes this stuff? System date is fetched by NTP finely, and date function in console also returns correct date.

Again, it seems that USB sub-system lives its own life, not related to others:

Aug  1 03:00:36 host usb: USB /dev/sda2(ntfs) failed to mount At the first try!
Aug  1 03:00:36 host kernel: usb 2-2: new high speed USB device using ehci_hcd and address 2
Aug  1 03:00:36 host usb: USB ntfs fs at /dev/sda2 mounted on /tmp/mnt/HHX.
Aug  1 03:00:38 host kernel: usbcore: registered new interface driver usbserial
Aug  1 03:00:38 host kernel: usbcore: registered new interface driver usbserial_generic
Aug  1 03:00:38 host kernel: usbserial: USB Serial Driver core
Aug  1 03:00:41 host kernel: usb 2-2: GSM modem (1-port) converter now attached to ttyUSB0
Aug  1 03:00:41 host kernel: usb 2-2: GSM modem (1-port) converter now attached to ttyUSB1
Aug  1 03:00:41 host kernel: usb 2-2: GSM modem (1-port) converter now attached to ttyUSB2
Aug  1 03:00:41 host kernel: usbcore: registered new interface driver option
Jul 28 04:04:43 host usb: USB /dev/sda1(ntfs) failed to mount At the first try!
Jul 28 04:04:43 host usb: USB ntfs fs at /dev/sda1 mounted on /tmp/mnt/SYSTEM.
Aug  1 03:00:35 host kernel: usb 2-2: new high speed USB device using ehci_hcd and address 2
Aug  1 03:00:36 host usb: USB /dev/sda1(ntfs) failed to mount At the first try!
Aug  1 03:00:37 host usb: USB ntfs fs at /dev/sda1 mounted on /tmp/mnt/SYSTEM.
Aug  1 03:00:37 host kernel: usbcore: registered new interface driver usbserial
Aug  1 03:00:37 host kernel: usbcore: registered new interface driver usbserial_generic
Aug  1 03:00:37 host kernel: usbserial: USB Serial Driver core
Jul 28 07:43:23 host kernel: usb 2-2: GSM modem (1-port) converter now attached to ttyUSB0
Jul 28 07:43:23 host kernel: usb 2-2: GSM modem (1-port) converter now attached to ttyUSB1
Jul 28 07:43:23 host kernel: usb 2-2: GSM modem (1-port) converter now attached to ttyUSB2
Jul 28 07:43:23 host kernel: usbcore: registered new interface driver option
Jul 28 07:44:38 host usb: USB ext4 fs at /dev/sda3 mounted on /tmp/mnt/DOWNLOADS.
Jul 28 07:45:16 host usb: USB /dev/sda2(ntfs) failed to mount At the first try!
Jul 28 07:45:16 host usb: USB ntfs fs at /dev/sda2 mounted on /tmp/mnt/HHX.

Why 1st of August? WTF?
It is very cumbersome to troubleshoot without knowing real event time.

 

[ColinTaylor]

The 1st August entries are the default date/time when the router boots before it has connected to an NTP server.

So it looks like you're in a time zone that is UTC +3 hours? So it appears that transmission is logging using UTC time whereas the other entries are using your local time.

 

[Marko Polo]

The 1st August entries are the default date/time when the router boots before it has connected to an NTP server.

So time is not persistent anywhere in nvram? The device resets time on each reboot and cannot keep it without NTP?

 

[ColinTaylor]

So time is not persistent anywhere in nvram? The device resets time on each reboot and cannot keep it without NTP?

Correct. The same as almost all consumer routers, there's no battery backup for the date/time.

 

[Marko Polo]

Your words doesn't explain the last log: why time has changed twicely between 3AM and 7AM? My reboot is scheduled only on 4AM, and the time shouldn't have been changed on 3AM.

 

[ColinTaylor]

My reboot is scheduled only on 4AM, and the time shouldn't have been changed on 3AM.

It didn't change at 3AM. Like I said, the default date and time when the router boots is 1st August 00:00, this is then adjusted for your time zone to 1st August 03:00. So all those entries are non-real times.

 

[Marko Polo]

So all those entries are non-real times.

So where did it get those two real records between unreal?

Aug 1 03:00:41 host kernel: usb 2-2: GSM modem (1-port) converter now attached to ttyUSB2
Aug 1 03:00:41 host kernel: usbcore: registered new interface driver option
Jul 28 04:04:43 host usb: USB /dev/sda1(ntfs) failed to mount At the first try!
Jul 28 04:04:43 host usb: USB ntfs fs at /dev/sda1 mounted on /tmp/mnt/SYSTEM.
Aug 1 03:00:35 host kernel: usb 2-2: new high speed USB device using ehci_hcd and address 2
Aug 1 03:00:36 host usb: USB /dev/sda1(ntfs) failed to mount At the first try!

 

[Marko Polo]

So it appears that transmission is logging using UTC time whereas the other entries are using your local time.

And here they say that transmission fetches timezone from the device. Did you experience such issues with other apps? Is it app-specific setting or there is some common practice?

 

[ColinTaylor]

This is the strange part. It looks like your router booted up at 04:00, but the messages are incomplete. Perhaps indicating that it hung? Or did you edit out sections of the log?

Aug  1 03:00:36 host usb: USB /dev/sda2(ntfs) failed to mount At the first try!
Aug  1 03:00:36 host kernel: usb 2-2: new high speed USB device using ehci_hcd and address 2
Aug  1 03:00:36 host usb: USB ntfs fs at /dev/sda2 mounted on /tmp/mnt/HHX.
Aug  1 03:00:38 host kernel: usbcore: registered new interface driver usbserial
Aug  1 03:00:38 host kernel: usbcore: registered new interface driver usbserial_generic
Aug  1 03:00:38 host kernel: usbserial: USB Serial Driver core
Aug  1 03:00:41 host kernel: usb 2-2: GSM modem (1-port) converter now attached to ttyUSB0
Aug  1 03:00:41 host kernel: usb 2-2: GSM modem (1-port) converter now attached to ttyUSB1
Aug  1 03:00:41 host kernel: usb 2-2: GSM modem (1-port) converter now attached to ttyUSB2
Aug  1 03:00:41 host kernel: usbcore: registered new interface driver option
Jul 28 04:04:43 host usb: USB /dev/sda1(ntfs) failed to mount At the first try!
Jul 28 04:04:43 host usb: USB ntfs fs at /dev/sda1 mounted on /tmp/mnt/SYSTEM.

And then it booted again at about 07:42. But again, sections of the log are missing.

Aug  1 03:00:35 host kernel: usb 2-2: new high speed USB device using ehci_hcd and address 2
Aug  1 03:00:36 host usb: USB /dev/sda1(ntfs) failed to mount At the first try!
Aug  1 03:00:37 host usb: USB ntfs fs at /dev/sda1 mounted on /tmp/mnt/SYSTEM.
Aug  1 03:00:37 host kernel: usbcore: registered new interface driver usbserial
Aug  1 03:00:37 host kernel: usbcore: registered new interface driver usbserial_generic
Aug  1 03:00:37 host kernel: usbserial: USB Serial Driver core
Jul 28 07:43:23 host kernel: usb 2-2: GSM modem (1-port) converter now attached to ttyUSB0
Jul 28 07:43:23 host kernel: usb 2-2: GSM modem (1-port) converter now attached to ttyUSB1
Jul 28 07:43:23 host kernel: usb 2-2: GSM modem (1-port) converter now attached to ttyUSB2
Jul 28 07:43:23 host kernel: usbcore: registered new interface driver option
Jul 28 07:44:38 host usb: USB ext4 fs at /dev/sda3 mounted on /tmp/mnt/DOWNLOADS.
Jul 28 07:45:16 host usb: USB /dev/sda2(ntfs) failed to mount At the first try!
Jul 28 07:45:16 host usb: USB ntfs fs at /dev/sda2 mounted on /tmp/mnt/HHX.

 

[Marko Polo]

Perhaps indicating that it hung? Or did you edit out sections of the log?

Hm, maybe it hung. Will observe the logs further.
No, I didn't edit sections, I set up log server which eats everything and just copy logs from there without altering.
I am going to utilize some automated log parsing solution to accumulate some stats, therefore reliable log time statements matter for me.

 

[ColinTaylor]

By way of an example, here is the kind of entries that are missing before that 2nd part of the logs. Bearing in mind I have a different router in a different time zone and different firmware, but you get the idea.

Jan  1 00:00:12 syslogd started: BusyBox v1.25.1
Jan  1 00:00:12 kernel: klogd started: BusyBox v1.25.1 (2017-07-20 06:47:38 MST)
Jan  1 00:00:12 kernel: Linux version 2.6.36.4brcmarm (root@ASUS-AJ082535) (gcc version 4.5.3 (Buildroot 2012.02) ) #1 SMP PREEMPT Thu Jul 20 06:53:00 MST 2017
Jan  1 00:00:12 kernel: CPU: ARMv7 Processor [413fc090] revision 0 (ARMv7), cr=10c53c7f
Jan  1 00:00:12 kernel: CPU: VIPT nonaliasing data cache, VIPT nonaliasing instruction cache
Jan  1 00:00:12 kernel: Machine: Northstar Prototype
Jan  1 00:00:12 kernel: Ignoring unrecognised tag 0x00000000
Jan  1 00:00:12 kernel: bootconsole [earlycon0] enabled
Jan  1 00:00:12 kernel: Memory policy: ECC disabled, Data cache writealloc
Jan  1 00:00:12 kernel: MPCORE found at 19020000
Jan  1 00:00:12 kernel: PERCPU: Embedded 7 pages/cpu @c8215000 s5504 r8192 d14976 u65536
Jan  1 00:00:12 kernel: pcpu-alloc: s5504 r8192 d14976 u65536 alloc=16*4096
Jan  1 00:00:12 kernel: pcpu-alloc: [0] 0 [0] 1
Jan  1 00:00:12 kernel: Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 60416
Jan  1 00:00:12 kernel: Kernel command line: root=/dev/mtdblock2 console=ttyS0,115200 init=/sbin/preinit earlyprintk debug
Jan  1 00:00:12 kernel: PID hash table entries: 1024 (order: 0, 4096 bytes)
Jan  1 00:00:12 kernel: Dentry cache hash table entries: 32768 (order: 5, 131072 bytes)
Jan  1 00:00:12 kernel: Inode-cache hash table entries: 16384 (order: 4, 65536 bytes)
Jan  1 00:00:12 kernel: Memory: 128MB 128MB = 256MB total
Jan  1 00:00:12 kernel: Memory: 255416k/255416k available, 6728k reserved, 0K highmem
Jan  1 00:00:12 kernel: Virtual kernel memory layout:
Jan  1 00:00:12 kernel:     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
Jan  1 00:00:12 kernel:     fixmap  : 0xfff00000 - 0xfffe0000   ( 896 kB)
Jan  1 00:00:12 kernel:     DMA     : 0xf7e00000 - 0xffe00000   ( 128 MB)
Jan  1 00:00:12 kernel:     vmalloc : 0xd0800000 - 0xf0000000   ( 504 MB)
Jan  1 00:00:12 kernel:     lowmem  : 0xc0000000 - 0xd0000000   ( 256 MB)
Jan  1 00:00:12 kernel:     modules : 0xbf000000 - 0xc0000000   (  16 MB)
Jan  1 00:00:12 kernel:       .init : 0xc0008000 - 0xc003e000   ( 216 kB)
Jan  1 00:00:12 kernel:       .text : 0xc003e000 - 0xc03bf000   (3588 kB)
Jan  1 00:00:12 kernel:       .data : 0xc03d8000 - 0xc03fbf60   ( 144 kB)
Jan  1 00:00:12 kernel: SLUB: Genslabs=11, HWalign=32, Order=0-3, MinObjects=0, CPUs=2, Nodes=1
Jan  1 00:00:12 kernel: Hierarchical RCU implementation.
Jan  1 00:00:12 kernel:     RCU-based detection of stalled CPUs is disabled.
Jan  1 00:00:12 kernel:     Verbose stalled-CPUs detection is disabled.
Jan  1 00:00:12 kernel: NR_IRQS:256
Jan  1 00:00:12 kernel: MPCORE GIC init
Jan  1 00:00:12 kernel: External imprecise Data abort at addr=0x0, fsr=0x1c06 ignored.
Jan  1 00:00:12 kernel: MPCORE Global Timer Clock 500000000Hz
Jan  1 00:00:12 kernel: Calibrating delay loop... 1998.84 BogoMIPS (lpj=9994240)
Jan  1 00:00:12 kernel: pid_max: default: 32768 minimum: 301
Jan  1 00:00:12 kernel: Mount-cache hash table entries: 512
Jan  1 00:00:12 kernel: CPU: Testing write buffer coherency: ok
Jan  1 00:00:12 kernel: MPCORE Private timer setup CPU0
Jan  1 00:00:12 kernel: Calibrating local timer... 499.860MHz.
Jan  1 00:00:12 kernel: L310: cache controller enabled 16 ways, CACHE_ID 0x410000c8, AUX_CTRL 0x7a130000
Jan  1 00:00:12 kernel: CPU1: Booted secondary processor
Jan  1 00:00:12 kernel: MPCORE Private timer setup CPU1
Jan  1 00:00:12 kernel: Brought up 2 CPUs
Jan  1 00:00:12 kernel: SMP: Total of 2 processors activated (3997.69 BogoMIPS).
Jan  1 00:00:12 kernel: devtmpfs: initialized
Jan  1 00:00:12 kernel: atomic64 test passed
Jan  1 00:00:12 kernel: NET: Registered protocol family 16
Jan  1 00:00:12 kernel: Found a AMD NAND flash:
Jan  1 00:00:12 kernel: Total size:  128MB
Jan  1 00:00:12 kernel: Block size:  128KB
Jan  1 00:00:12 kernel: Page Size:   2048B
Jan  1 00:00:12 kernel: OOB Size:    64B
Jan  1 00:00:12 kernel: Sector size: 512B
Jan  1 00:00:12 kernel: Spare size:  16B
Jan  1 00:00:12 kernel: ECC level:   8 (8-bit)
Jan  1 00:00:12 kernel: Device ID: 0x 1 0xf1 0x80 0x1d 0x 1 0xf1
Jan  1 00:00:12 kernel: CCA UART Clock Config: Sel=1 Ovr=1 Div=48
Jan  1 00:00:12 kernel: CCA UART Clock rate 100000000Hz
Jan  1 00:00:12 kernel: bio: create slab <bio-0> at 0
Jan  1 00:00:12 kernel: Switching to clocksource mpcore_gtimer
Jan  1 00:00:12 kernel: NET: Registered protocol family 2
Jan  1 00:00:12 kernel: IP route cache hash table entries: 2048 (order: 1, 8192 bytes)
Jan  1 00:00:12 kernel: TCP established hash table entries: 8192 (order: 4, 65536 bytes)
Jan  1 00:00:12 kernel: TCP bind hash table entries: 8192 (order: 4, 98304 bytes)
Jan  1 00:00:12 kernel: TCP: Hash tables configured (established 8192 bind 8192)
Jan  1 00:00:12 kernel: TCP reno registered
Jan  1 00:00:12 kernel: UDP hash table entries: 128 (order: 0, 4096 bytes)
Jan  1 00:00:12 kernel: UDP-Lite hash table entries: 128 (order: 0, 4096 bytes)
Jan  1 00:00:12 kernel: NET: Registered protocol family 1
Jan  1 00:00:12 kernel: PCI: no core
Jan  1 00:00:12 kernel: PCI: no core
Jan  1 00:00:12 kernel: PCI: scanning bus 0
Jan  1 00:00:12 kernel: PCI: Fixing up bus 0
Jan  1 00:00:12 kernel: PCIE1 link=1
Jan  1 00:00:12 kernel: PCIE1 switching to GEN2
Jan  1 00:00:12 kernel: PCIE1 link=1
Jan  1 00:00:12 kernel: PCI: Fixing up bus 0
Jan  1 00:00:12 kernel: PCI: bus0: Fast back to back transfers disabled
Jan  1 00:00:12 kernel: PCI: Fixing up bus 1
Jan  1 00:00:12 kernel: PCI: bus1: Fast back to back transfers disabled
Jan  1 00:00:12 kernel: pci 0001:00:00.0: BAR 8: assigned [mem 0x08000000-0x080fffff]
Jan  1 00:00:12 kernel: pci 0001:01:00.0: BAR 0: assigned [mem 0x08000000-0x08007fff 64bit]
Jan  1 00:00:12 kernel: pci 0001:01:00.0: BAR 0: set to [mem 0x08000000-0x08007fff 64bit] (PCI address [0x8000000-0x8007fff]
Jan  1 00:00:12 kernel: pci 0001:00:00.0: PCI bridge to [bus 01-01]
Jan  1 00:00:12 kernel: pci 0001:00:00.0:   bridge window [io  disabled]
Jan  1 00:00:12 kernel: pci 0001:00:00.0:   bridge window [mem 0x08000000-0x080fffff]
Jan  1 00:00:12 kernel: pci 0001:00:00.0:   bridge window [mem pref disabled]
Jan  1 00:00:12 kernel: PCIE2 link=1
Jan  1 00:00:12 kernel: PCIE2 switching to GEN2
Jan  1 00:00:12 kernel: PCIE2 link=1
Jan  1 00:00:12 kernel: PCI: Fixing up bus 0
Jan  1 00:00:12 kernel: PCI: bus0: Fast back to back transfers disabled
Jan  1 00:00:12 kernel: PCI: Fixing up bus 2
Jan  1 00:00:12 kernel: PCI: bus2: Fast back to back transfers disabled
Jan  1 00:00:12 kernel: pci 0002:00:00.0: BAR 8: assigned [mem 0x40000000-0x400fffff]
Jan  1 00:00:12 kernel: pci 0002:02:00.0: BAR 0: assigned [mem 0x40000000-0x40007fff 64bit]
Jan  1 00:00:12 kernel: pci 0002:02:00.0: BAR 0: set to [mem 0x40000000-0x40007fff 64bit] (PCI address [0x40000000-0x40007fff]
Jan  1 00:00:12 kernel: pci 0002:00:00.0: PCI bridge to [bus 02-02]
Jan  1 00:00:12 kernel: pci 0002:00:00.0:   bridge window [io  disabled]
Jan  1 00:00:12 kernel: pci 0002:00:00.0:   bridge window [mem 0x40000000-0x400fffff]
Jan  1 00:00:12 kernel: pci 0002:00:00.0:   bridge window [mem pref disabled]
Jan  1 00:00:12 kernel: PCIE3 link=0
Jan  1 00:00:12 kernel: VFS: Disk quotas dquot_6.5.2
Jan  1 00:00:12 kernel: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
Jan  1 00:00:12 kernel: squashfs: version 4.0 (2009/01/31) Phillip Lougher
Jan  1 00:00:12 kernel: fuse init (API version 7.15)
Jan  1 00:00:12 kernel: msgmni has been set to 498
Jan  1 00:00:12 kernel: io scheduler noop registered (default)
Jan  1 00:00:12 kernel: io scheduler deadline registered
Jan  1 00:00:12 kernel: io scheduler cfq registered
Jan  1 00:00:12 kernel: Serial: 8250/16550 driver, 2 ports, IRQ sharing disabled
Jan  1 00:00:12 kernel: serial8250.0: ttyS0 at MMIO 0x18000300 (irq = 117) is a 16550
Jan  1 00:00:12 kernel: console [ttyS0] enabled, bootconsole disabled
Jan  1 00:00:12 kernel: serial8250.0: ttyS1 at MMIO 0x18000400 (irq = 117) is a 16550
Jan  1 00:00:12 kernel: brd: module loaded
Jan  1 00:00:12 kernel: loop: module loaded
Jan  1 00:00:12 kernel: pflash: found no supported devices
Jan  1 00:00:12 kernel: bcmsflash: found no supported devices
Jan  1 00:00:12 kernel: Boot partition size = 524288(0x80000)
Jan  1 00:00:12 kernel: lookup_nflash_rootfs_offset: offset = 0x200000
Jan  1 00:00:12 kernel: nflash: squash filesystem with lzma found at block 29
Jan  1 00:00:12 kernel: Creating 4 MTD partitions on "nflash":
Jan  1 00:00:12 kernel: 0x000000000000-0x000000080000 : "boot"
Jan  1 00:00:12 kernel: 0x000000080000-0x000000200000 : "nvram"
Jan  1 00:00:12 kernel: 0x000000200000-0x000004000000 : "linux"
Jan  1 00:00:12 kernel: 0x0000003a86b4-0x000004000000 : "rootfs"

 

[ColinTaylor]

Jan  1 00:00:12 kernel: PPP generic driver version 2.4.2
Jan  1 00:00:12 kernel: PPP MPPE Compression module registered
Jan  1 00:00:12 kernel: NET: Registered protocol family 24
Jan  1 00:00:12 kernel: PPTP driver version 0.8.5
Jan  1 00:00:12 kernel: === PPTP init ===
Jan  1 00:00:12 kernel: Mirror/redirect action on
Jan  1 00:00:12 kernel: u32 classifier
Jan  1 00:00:12 kernel:     Actions configured
Jan  1 00:00:12 kernel: Netfilter messages via NETLINK v0.30.
Jan  1 00:00:12 kernel: nf_conntrack version 0.5.0 (3990 buckets, 15960 max)
Jan  1 00:00:12 kernel: xt_time: kernel timezone is -0000
Jan  1 00:00:12 kernel: ip_tables: (C) 2000-2006 Netfilter Core Team
Jan  1 00:00:12 kernel: TCP cubic registered
Jan  1 00:00:12 kernel: NET: Registered protocol family 10
Jan  1 00:00:12 kernel: ip6_tables: (C) 2000-2006 Netfilter Core Team
Jan  1 00:00:12 kernel: NET: Registered protocol family 17
Jan  1 00:00:12 kernel: L2TP core driver, V2.0
Jan  1 00:00:12 kernel: PPPoL2TP kernel driver, V2.0
Jan  1 00:00:12 kernel: 802.1Q VLAN Support v1.8 Ben Greear <greearb@candelatech.com>
Jan  1 00:00:12 kernel: All bugs added by David S. Miller <davem@redhat.com>
Jan  1 00:00:12 kernel: Registering the dns_resolver key type
Jan  1 00:00:12 kernel: Northstar brcmnand NAND Flash Controller driver, Version 0.1 (c) Broadcom Inc. 2012
Jan  1 00:00:12 kernel: NAND device: Manufacturer ID: 0x01, Chip ID: 0xf1 (AMD NAND 128MiB 3,3V 8-bit)
Jan  1 00:00:12 kernel: Spare area=64 eccbytes 56, ecc bytes located at:
Jan  1 00:00:12 kernel:  2 3 4 5 6 7 8 9 10 11 12 13 14 15 18 19 20 21 22 23 24 25 26 27 28 29 30 31 34 35 36 37 38 39 40 41 42 43 44 45 46 47 50 51 52 53 54 55 56 57 58 59 60 61 62 63
Jan  1 00:00:12 kernel: Available 7 bytes at (off,len):
Jan  1 00:00:12 kernel: (1,1) (16,2) (32,2) (48,2) (0,0) (0,0) (0,0) (0,0)
Jan  1 00:00:12 kernel: Scanning device for bad blocks
Jan  1 00:00:12 kernel: Options: NO_AUTOINCR,NO_READRDY,BBT_SCAN2NDPAGE,
Jan  1 00:00:12 kernel: Creating 2 MTD partitions on "brcmnand":
Jan  1 00:00:12 kernel: 0x000004000000-0x000008000000 : "brcmnand"
Jan  1 00:00:12 kernel: 0x000004000000-0x000006000000 : "jffs2"
Jan  1 00:00:12 kernel: VFS: Mounted root (squashfs filesystem) readonly on device 31:3.
Jan  1 00:00:12 kernel: devtmpfs: mounted
Jan  1 00:00:12 kernel: Freeing init memory: 216K
Jan  1 00:00:12 kernel: et: module license 'Proprietary' taints kernel.
Jan  1 00:00:12 kernel: Disabling lock debugging due to kernel taint
Jan  1 00:00:12 kernel: et_module_init: passivemode set to 0x0
Jan  1 00:00:12 kernel: et_module_init: txworkq set to 0x1
Jan  1 00:00:12 kernel: et_module_init: et_txq_thresh set to 0x400
Jan  1 00:00:12 kernel: eth0: Broadcom BCM47XX 10/100/1000 Mbps Ethernet Controller 6.37.14.86 (r456083)
Jan  1 00:00:12 kernel: wl_module_init: passivemode set to 0x0
Jan  1 00:00:12 kernel: wl_module_init: txworkq set to 0x1
Jan  1 00:00:12 kernel: eth1: Broadcom BCM4360 802.11 Wireless Controller 6.37.14.86 (r456083)
Jan  1 00:00:12 kernel: eth2: Broadcom BCM4360 802.11 Wireless Controller 6.37.14.86 (r456083)
Jan  1 00:00:12 kernel: JFFS2 version 2.2. (NAND) © 2001-2006 Red Hat, Inc.
Jan  1 00:00:12 kernel: usbcore: registered new interface driver usbfs
Jan  1 00:00:12 kernel: usbcore: registered new interface driver hub
Jan  1 00:00:12 kernel: usbcore: registered new device driver usb
Jan  1 00:00:12 syslog: module ledtrig-usbdev not found in modules.dep
Jan  1 00:00:12 syslog: module leds-usb not found in modules.dep
Jan  1 00:00:12 kernel: SCSI subsystem initialized
Jan  1 00:00:12 kernel: Initializing USB Mass Storage driver...
Jan  1 00:00:12 kernel: usbcore: registered new interface driver usb-storage
Jan  1 00:00:12 kernel: USB Mass Storage support registered.
Jan  1 00:00:13 syslog: module vfat not found in modules.dep
Jan  1 00:00:13 kernel: jnl: driver (lke_8.9.0, Apr  9 2014 16:56:06, LBD=ON) loaded at bf5f3000
Jan  1 00:00:13 kernel: ufsd:: trace mask set to 0000000f
Jan  1 00:00:13 kernel: ufsd: driver (lke_8.9.0 lke_8.9.0_r225078_b43, LBD=ON, delalloc, acl, ioctl, ugm, sd(1), wb, tr) loaded at bf600000
Jan  1 00:00:13 kernel: NTFS support included
Jan  1 00:00:13 kernel: Hfs+/HfsJ support included
Jan  1 00:00:13 kernel: optimized: speed
Jan  1 00:00:13 kernel: Build_for__ASUS_PRODUCTS_003_lke_8.9.0_r225078_b43
Jan  1 00:00:13 kernel: exFAT: Version 1.2.9
Jan  1 00:00:13 kernel: xhci_hcd 0000:00:0c.0: xHCI Host Controller
Jan  1 00:00:13 kernel: xhci_hcd 0000:00:0c.0: new USB bus registered, assigned bus number 1
Jan  1 00:00:13 kernel: xhci_hcd 0000:00:0c.0: irq 112, io mem 0x18023000
Jan  1 00:00:13 kernel: xhci_hcd 0000:00:0c.0: Failed to enable MSI-X
Jan  1 00:00:13 kernel: xhci_hcd 0000:00:0c.0: failed to allocate MSI entry
Jan  1 00:00:13 kernel: usb usb1: No SuperSpeed endpoint companion for config 1  interface 0 altsetting 0 ep 129: using minimum values
Jan  1 00:00:13 kernel: hub 1-0:1.0: USB hub found
Jan  1 00:00:13 kernel: hub 1-0:1.0: 1 port detected
Jan  1 00:00:13 kernel: [xhci-hub] usb2mode:[0]
Jan  1 00:00:13 kernel: ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
Jan  1 00:00:13 kernel: ehci_hcd 0000:00:0b.1: EHCI Host Controller
Jan  1 00:00:13 kernel: ehci_hcd 0000:00:0b.1: new USB bus registered, assigned bus number 2
Jan  1 00:00:13 kernel: ehci_hcd 0000:00:0b.1: irq 111, io mem 0x18021000
Jan  1 00:00:13 kernel: ehci_hcd 0000:00:0b.1: USB 0.0 started, EHCI 1.00
Jan  1 00:00:13 kernel: hub 2-0:1.0: USB hub found
Jan  1 00:00:13 kernel: hub 2-0:1.0: 2 ports detected
Jan  1 00:00:13 kernel: ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
Jan  1 00:00:13 kernel: ohci_hcd 0000:00:0b.0: OHCI Host Controller
Jan  1 00:00:13 kernel: ohci_hcd 0000:00:0b.0: new USB bus registered, assigned bus number 3
Jan  1 00:00:13 kernel: ohci_hcd 0000:00:0b.0: irq 111, io mem 0x18022000
Jan  1 00:00:13 kernel: hub 3-0:1.0: USB hub found
Jan  1 00:00:13 kernel: hub 3-0:1.0: 2 ports detected
Jan  1 00:00:13 kernel: usbcore: registered new interface driver usblp
Jan  1 00:00:14 kernel: usbcore: registered new interface driver asix
Jan  1 00:00:14 kernel: usbcore: registered new interface driver cdc_ether
Jan  1 00:00:14 kernel: usbcore: registered new interface driver rndis_host
Jan  1 00:00:14 kernel: cdc_ncm: 14-Mar-2012
Jan  1 00:00:14 kernel: usbcore: registered new interface driver cdc_ncm
Jan  1 00:00:14 kernel: usbcore: registered new interface driver cdc_wdm
Jan  1 00:00:14 kernel: usbcore: registered new interface driver qmi_wwan
Jan  1 00:00:14 kernel: cdc_mbim: loaded
Jan  1 00:00:14 kernel: usbcore: registered new interface driver cdc_mbim
Jan  1 00:00:14 kernel: usb 2-2: new high speed USB device using ehci_hcd and address 2
Jan  1 00:00:14 kernel: scsi0 : usb-storage 2-2:1.0
Jan  1 00:00:14 kernel: device vlan1 entered promiscuous mode
Jan  1 00:00:14 kernel: device eth0 entered promiscuous mode
Jan  1 00:00:14 kernel: device eth1 entered promiscuous mode
Jan  1 00:00:14 kernel: device eth2 entered promiscuous mode
Jan  1 00:00:14 kernel: br0: topology change detected, propagating
Jan  1 00:00:14 kernel: br0: port 3(eth2) entering forwarding state
Jan  1 00:00:14 kernel: br0: port 3(eth2) entering forwarding state
Jan  1 00:00:14 kernel: br0: topology change detected, propagating
Jan  1 00:00:14 kernel: br0: port 2(eth1) entering forwarding state
Jan  1 00:00:14 kernel: br0: port 2(eth1) entering forwarding state
Jan  1 00:00:14 kernel: br0: topology change detected, propagating
Jan  1 00:00:14 kernel: br0: port 1(vlan1) entering forwarding state
Jan  1 00:00:14 kernel: br0: port 1(vlan1) entering forwarding state
Jan  1 00:00:14 kernel: ADDRCONF(NETDEV_UP): vlan2: link is not ready
Jan  1 00:00:15 kernel: scsi 0:0:0:0: Direct-Access     Verbatim STORE N GO       1.01 PQ: 0 ANSI: 2
Jan  1 00:00:15 kernel: sd 0:0:0:0: Attached scsi generic sg0 type 0
Jan  1 00:00:15 kernel: sd 0:0:0:0: [sda] 31299584 512-byte logical blocks: (16.0 GB/14.9 GiB)
Jan  1 00:00:15 kernel: sd 0:0:0:0: [sda] Write Protect is off
Jan  1 00:00:15 kernel: sd 0:0:0:0: [sda] Assuming drive cache: write through
Jan  1 00:00:15 kernel: sd 0:0:0:0: [sda] Assuming drive cache: write through
Jan  1 00:00:15 kernel:  sda: sda1
Jan  1 00:00:15 kernel: sd 0:0:0:0: [sda] Assuming drive cache: write through
Jan  1 00:00:15 kernel: sd 0:0:0:0: [sda] Attached SCSI removable disk
Jan  1 00:00:15 hotplug[554]: USB ext4 fs at /dev/sda1 mounted on /tmp/mnt/VERBATIM
Jan  1 00:00:15 kernel: EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: user_xattr

 

[Marko Polo]

Yeah, I don't see such entries in my log. What verbosity level do you have?

 

[ColinTaylor]

Yeah, I don't see such entries in my log. What verbosity level do you have?

Just the defaults. "Default router message log level" = Notice, "Syslog log level" = Info.

 

[Marko Polo]

"Syslog log level" = Info.

Hm, interesting. I have Log only messages more urgent than = debug. It should be even more detailed than yours. Something is definitely lost in my logs

 

[Marko Polo]

I have firewall policy log = dropped + accepted, and syslog get flooded with these records. Can FW logs have highest priority than other kernel records and thus syslog wipes system records as space is over?
How to increase log capacity? Which setting in Merlin controls max syslog size?

 

[ColinTaylor]

I have firewall policy log = dropped + accepted, and syslog get flooded with these records. Can FW logs have highest priority than other kernel records and thus syslog wipes system records as space is over?
How to increase log capacity? Which setting in Merlin controls max syslog size?

What non-standard modifications have you made that might effect logging? How are you viewing the log, in the router's GUI presumably? In all cases you should at least see the following in the log at startup:

Jan  1 00:00:12 syslogd started: BusyBox v1.25.1
Jan  1 00:00:12 kernel: klogd started: BusyBox v1.25.1 (2017-07-20 06:47:38 MST)
Jan  1 00:00:12 kernel: Linux version 2.6.36.4brcmarm (root@ASUS-AJ082535) (gcc version 4.5.3 (Buildroot 2012.02) ) #1 SMP PREEMPT Thu Jul 20 06:53:00 MST 2017
Jan  1 00:00:12 kernel: CPU: ARMv7 Processor [413fc090] revision 0 (ARMv7), cr=10c53c7f
Jan  1 00:00:12 kernel: CPU: VIPT nonaliasing data cache, VIPT nonaliasing instruction cache
Jan  1 00:00:12 kernel: Machine: Northstar Prototype
Jan  1 00:00:12 kernel: Ignoring unrecognised tag 0x00000000
Jan  1 00:00:12 kernel: bootconsole [earlycon0] enabled
Jan  1 00:00:12 kernel: Memory policy: ECC disabled, Data cache writealloc
Jan  1 00:00:12 kernel: MPCORE found at 19020000
Jan  1 00:00:12 kernel: PERCPU: Embedded 7 pages/cpu @c8215000 s5504 r8192 d14976 u65536
Jan  1 00:00:12 kernel: pcpu-alloc: s5504 r8192 d14976 u65536 alloc=16*4096
Jan  1 00:00:12 kernel: pcpu-alloc: [0] 0 [0] 1
Jan  1 00:00:12 kernel: Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 60416
:
:
:

 

[Marko Polo]

What non-standard modifications have you made that might effect logging?

Nothing. Here is my settings:

How are you viewing the log, in the router's GUI presumably?

Presumably on the log server, but viewing /tmp/syslog.log gives the same picture. 90% of my syslog are firewall messages, transmission and dropbear. Nothing like you are showing here.
Other messages might have been overwritten by FW messages, but log server should remember everything. But it doesn't contains them either.
Will try to increase verbosity.

 

[ColinTaylor]

Rather than adding even more volume to the logs I suggest that you undo all of your changes and go back to a baseline. So turn off firewall logging, remove the remote log server entry and change the log levels back to the defaults. Also, temporarily disable transmission just in case that's the problem.

Now reboot the router and look at the log. You should now see the boot messages I posted above.

Assuming everything is OK start adding back in the changes one at a time, rebooting and checking the log after each change.