I2C is flooding journald log

[nkskjames]

only thing in journald in 30000 lines is i2c stuff

[shenki]

What does the journald log look like?

What is your kernel command line?

[shenki]

Booting Linux on physical CPU 0x0
Linux version 4.2.0-openbmc-20151028-1 (causten@causten-VirtualBox) (gcc version 4.9.3 (GCC) ) #1 Sun Nov 1 14:07:15 CST 2015
CPU: ARM926EJ-S [41069265] revision 5 (ARMv5TEJ), cr=0005317f
CPU: VIVT data cache, VIVT instruction cache
Machine model: Palmetto BMC
Memory policy: Data cache writeback
SOC Rev: 02010303
On node 0 totalpages: 114176
free_area_init_node: node 0, pgdat c0502680, node_mem_map dba79000
  Normal zone: 892 pages used for memmap
  Normal zone: 0 pages reserved
  Normal zone: 114176 pages, LIFO batch:31
UART IO MUX...
UART PIN MUX...
SCU LOCK: 00000001
DONE, MUX=cb000000 00fff0c0
CLOCK_CTRL=00000001
WDT0C=00000000
WDT2C=00000082
DLL=1
pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
pcpu-alloc: [0] 0 
Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 113284
Kernel command line: console=ttyS4,38400
PID hash table entries: 2048 (order: 1, 8192 bytes)
Dentry cache hash table entries: 65536 (order: 6, 262144 bytes)
Inode-cache hash table entries: 32768 (order: 5, 131072 bytes)
Memory: 431416K/456704K available (3536K kernel code, 171K rwdata, 1260K rodata, 160K init, 108K bss, 25288K reserved, 0K cma-reserved)
Virtual kernel memory layout:
    vector  : 0xffff0000 - 0xffff1000   (   4 kB)
    fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
    vmalloc : 0xdc000000 - 0xff000000   ( 560 MB)
    lowmem  : 0xc0000000 - 0xdbe00000   ( 446 MB)
    modules : 0xbf000000 - 0xc0000000   (  16 MB)
      .text : 0xc0008000 - 0xc04b7720   (4798 kB)
      .init : 0xc04b8000 - 0xc04e0000   ( 160 kB)
      .data : 0xc04e0000 - 0xc050ac68   ( 172 kB)
       .bss : 0xc050ac68 - 0xc0526028   ( 109 kB)
NR_IRQS:16 nr_irqs:16 16
Aspeed VIC Initiallized
clocksource: moxart_timer: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 39817925974 ns
sched_clock: 32 bits at 100 Hz, resolution 10000000ns, wraps every 21474836475000000ns
Calibrating delay loop... 190.87 BogoMIPS (lpj=954368)
pid_max: default: 32768 minimum: 301
Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
CPU: Testing write buffer coherency: ok
Setting up static identity map for 0x40008400 - 0x40008458
devtmpfs: initialized
clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
pinctrl core: initialized pinctrl subsystem
NET: Registered protocol family 16
DMA: preallocated 256 KiB pool for atomic coherent allocations
i2c-core: driver [dummy] registered
SCSI subsystem initialized
usbcore: registered new interface driver usbfs
usbcore: registered new interface driver hub
usbcore: registered new device driver usb
clocksource: Switched to clocksource moxart_timer
NET: Registered protocol family 2
TCP established hash table entries: 4096 (order: 2, 16384 bytes)
TCP bind hash table entries: 4096 (order: 2, 16384 bytes)
TCP: Hash tables configured (established 4096 bind 4096)
UDP hash table entries: 256 (order: 0, 4096 bytes)
UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
NET: Registered protocol family 1
RPC: Registered named UNIX socket transport module.
RPC: Registered udp transport module.
RPC: Registered tcp transport module.
RPC: Registered tcp NFSv4.1 backchannel transport module.
Trying to unpack rootfs image as initramfs...
Freeing initrd memory: 15964K (d0200000 - d1197000)
alarmtimer alarmtimer: no of_node; not parsing pinctrl DT
futex hash table entries: 256 (order: -1, 3072 bytes)
squashfs: version 4.0 (2009/01/31) Phillip Lougher
jffs2: version 2.2. (NAND) (SUMMARY)  © 2001-2006 Red Hat, Inc.
io scheduler noop registered (default)
Serial: 8250/16550 driver, 6 ports, IRQ sharing disabled
serial8250 serial8250: no of_node; not parsing pinctrl DT
1e783000.serial: ttyS0 at MMIO 0x1e783000 (irq = 22, base_baud = 115200) is a 16550A
1e78d000.serial: ttyS1 at MMIO 0x1e78d000 (irq = 23, base_baud = 115200) is a 16550A
1e78e000.serial: ttyS2 at MMIO 0x1e78e000 (irq = 24, base_baud = 115200) is a 16550A
1e78f000.serial: ttyS3 at MMIO 0x1e78f000 (irq = 25, base_baud = 115200) is a 16550A
console [ttyS4] disabled
1e784000.serial: ttyS4 at MMIO 0x1e784000 (irq = 26, base_baud = 115200) is a 16550A
console [ttyS4] enabled
1e787000.serial: ttyS5 at MMIO 0x1e787000 (irq = 26, base_baud = 115200) is a 16550A
brd: module loaded
loop: module loaded
i2c-core: driver [at24] registered
bt-host 1e789140.ibt: Found bt host device
ftgmac100 1e660000.ethernet: Using NCSI interface
ftgmac100 1e660000.ethernet: Read MAC address from chip a2:16:25:3f:42:a0
ftmac100: Loading version 0.2 ...
ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
usbcore: registered new interface driver cdc_acm
cdc_acm: USB Abstract Control Model driver for USB modems and ISDN adapters
usbcore: registered new interface driver usb-storage
usbcore: registered new interface driver usbserial
usbcore: registered new interface driver usbserial_generic
usbserial: USB Serial support registered for generic
mousedev: PS/2 mouse device common for all mice
i2c-core: driver [qt1070] registered
i2c-core: driver [rtc-ds1307] registered
i2c-core: driver [rtc-rv3029c2] registered
aspeed-rtc 1e781000.rtc: rtc core: registered 1e781000.rtc as rtc0
i2c /dev entries driver
ast_i2c_probe
aspeed_i2c_global_init
got global data da112180
got regs at f018a040
requesting irq 18
pclk = 48000000 
i2c-dev: adapter [Aspeed i2c at f018a040] registered as minor 0
i2c i2c-0: adapter [Aspeed i2c at f018a040] registered
bus_id 0
I2C: Aspeed i2c at f018a040: AST I2C adapter [100 khz]
ast_i2c_probe
aspeed_i2c_global_init
got global data da112180
got regs at f018a080
requesting irq 18
pclk = 48000000 
i2c-dev: adapter [Aspeed i2c at f018a080] registered as minor 1
i2c i2c-1: adapter [Aspeed i2c at f018a080] registered
bus_id 1
I2C: Aspeed i2c at f018a080: AST I2C adapter [100 khz]
i2c-core: driver [i2c-slave-eeprom] registered
i2c-core: driver [lm75] registered
i2c-core: driver [nct7904] registered
aspeed_wdt 1e785000.wdt: rate 48000000, max timeout 5, timeout 5
usbcore: registered new interface driver usbhid
usbhid: USB HID core driver
ip_tables: (C) 2000-2006 Netfilter Core Team
NET: Registered protocol family 17
aspeed-rtc 1e781000.rtc: setting system clock to 2015-10-01 21:52:26 UTC (1443736346)
Freeing unused kernel memory: 160K (c04b8000 - c04e0000)
random: systemd urandom read with 84 bits of entropy available
systemd[1]: systemd 225 running in system mode. (-PAM -AUDIT -SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP -LIBCRYPTSETUP -GCRYPT -GNUTLS +ACL -XZ -LZ4 -SECCOMP +BLKID -ELFUTILS +KMOD -IDN)
systemd[1]: Detected architecture arm.
systemd[1]: Set hostname to <palmetto>.
systemd[1]: Initializing machine ID from random generator.
systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
systemd[1]: Started Forward Password Requests to Wall Directory Watch.
systemd[1]: Reached target Paths.
systemd[1]: Reached target Swap.
systemd[1]: Created slice Root Slice.
systemd[1]: Listening on networkd rtnetlink socket.
systemd[1]: Listening on /dev/initctl Compatibility Named Pipe.
systemd[1]: Created slice System Slice.
systemd[1]: Created slice system-serial\x2dgetty.slice.
systemd[1]: Listening on Journal Socket.
systemd[1]: Starting Remount Root and Kernel File Systems...
systemd[1]: Starting Apply Kernel Variables...
systemd[1]: Created slice User and Session Slice.
systemd[1]: Mounting Configuration File System...
systemd[1]: Listening on Journal Socket (/dev/log).
systemd[1]: Created slice system-getty.slice.
systemd[1]: Reached target Slices.
systemd[1]: Listening on udev Kernel Socket.
systemd[1]: Listening on udev Control Socket.
systemd[1]: Mounting Debug File System...
systemd[1]: Reached target Remote File Systems.
systemd[1]: Listening on Syslog Socket.
systemd[1]: Starting Journal Service...
systemd[1]: Mounting Temporary Directory...
systemd[1]: Mounted Configuration File System.
systemd[1]: Mounted Debug File System.
systemd[1]: Mounted Temporary Directory.
systemd[1]: Started Remount Root and Kernel File Systems.
systemd[1]: Started Apply Kernel Variables.
systemd[1]: Started Journal Service.
systemd-journald[388]: Received request to flush runtime journal from PID 1
ftgmac100: NCSI dev is up
random: nonblocking pool is initialized

[shenki]

cat /proc/cmdline 
console=ttyS4,38400

[nkskjames]

= instantiate a hwmon (this is barreleye)
echo nct7904 0x2e > /sys/bus/i2c/devices/i2c-6/new_device

= the tmp421 temperature sensor will cause same behavior on palmetto.

= set pwm to max
echo 255 > /sys/class/hwmon/hwmon0/pwm1

I get this in console (issue #11)
ystemd-journald[388]: /dev/kmsg buffer overrun, some messages lost.
root@palmetto:/ssystemd-journald[388]: /dev/kmsg buffer overrun, some messages lost.

I need to recreate to get log entries.

[nkskjames]

This is on Palmetto
echo tmp423 0x4c > /sys/bus/i2c/devices/i2c-2/new_device

lots of these lines in journald log
Oct 31 23:13:18 palmetto kernel: i2c 2-004c: uevent
Oct 31 23:13:18 palmetto kernel: i2c 2-004c: uevent
Oct 31 23:13:18 palmetto kernel: i2c 2-004c: uevent
Oct 31 23:13:18 palmetto kernel: i2c 2-004c: uevent
Oct 31 23:13:18 palmetto kernel: i2c 2-004c: uevent
Oct 31 23:13:18 palmetto kernel: i2c 2-004c: uevent
Oct 31 23:13:18 palmetto kernel: i2c 2-004c: uevent
Oct 31 23:13:18 palmetto kernel: i2c 2-004c: uevent
Oct 31 23:13:18 palmetto kernel: i2c 2-004c: uevent
Oct 31 23:13:18 palmetto kernel: i2c 2-004c: uevent
Oct 31 23:13:18 palmetto kernel: i2c 2-004c: uevent
Oct 31 23:13:18 palmetto kernel: i2c 2-004c: uevent
Oct 31 23:13:18 palmetto kernel: i2c 2-004c: uevent
Oct 31 23:13:18 palmetto kernel: i2c 2-004c: uevent
Oct 31 23:13:18 palmetto kernel: i2c 2-004c: uevent
Oct 31 23:13:18 palmetto kernel: i2c 2-004c: uevent
Oct 31 23:13:18 palmetto kernel: i2c 2-004c: uevent
Oct 31 23:13:18 palmetto kernel: i2c 2-004c: uevent
Oct 31 23:13:18 palmetto kernel: i2c 2-004c: uevent
Oct 31 23:13:18 palmetto kernel: i2c 2-004c: uevent
Oct 31 23:13:18 palmetto kernel: i2c 2-004c: uevent
Oct 31 23:13:18 palmetto kernel: i2c 2-004c: uevent
Oct 31 23:13:18 palmetto kernel: i2c 2-004c: uevent

[shenki]

I am not familiar with journald. Does it show us all of the messages from the kernel, or is some kind of filtering performed?

Can you paste the output of dmesg | tail and /proc/cmdline?

On the specifics of your issue, this message comes from the core i2c code (https://github.com/torvalds/linux/blob/master/drivers/i2c/i2c-core.c#L492). It will take some more digging to work out why we're seeing this message, but it is harmless.

[nkskjames]

root@palmetto:~# dmesg|tail
i2c 2-004c: uevent
i2c 2-004c: uevent
i2c 2-004c: uevent
i2c 2-004c: uevent
i2c 2-004c: uevent
i2c 2-004c: uevent
i2c 2-004c: uevent
i2c 2-004c: uevent
i2c 2-004c: uevent
i2c 2-004c: uevent

dmesg totally rolled
root@palmetto:~# dmesg|head
i2c 2-004c: uevent
i2c 2-004c: uevent
i2c 2-004c: uevent
i2c 2-004c: uevent
i2c 2-004c: uevent
i2c 2-004c: uevent
i2c 2-004c: uevent
i2c 2-004c: uevent
i2c 2-004c: uevent
i2c 2-004c: uevent

root@palmetto:~# cat /proc/cmdline
console=ttyS4,38400

[jk-ozlabs]

Looks like we're hitting a systemd issue:

https://bugs.freedesktop.org/show_bug.cgi?id=76886

so perhaps we should disable CONFIG_I2C_DEBUG_CORE

[jk-ozlabs]

Should be fixed by cff17c4 and 3cd273e.