Logging SPAM (GPIO_IN=08)

sam_nazarko · 25 September 2015 15:42

With any luck this will be resolved in the September update

Sam

zxz · 28 September 2015 05:57

I can see the same issue also after September update

(Dmesg http://paste.osmc.io/emovebudol)

Full logs http://paste.osmc.io/decadipija

sam_nazarko · 28 September 2015 10:42

I am not sure what the issue could be then. It must be an upstream kernel bug.

zxz · 29 September 2015 05:05

Are there any downsides of getting these GPIO messages in the log ? Like extra memory consumption/exhaustion… also does it affect filesystem (increases usage size via files/logs) ?

bryan_martin · 3 October 2015 05:24

To enjoy the most amount of annoyance possible from this bug, try removing ‘quiet’ from /boot/cmdline.txt.

All of your terminals will be filled up with garbage in no time!

SMC: Open Source Media Center lilboy tty4

**lilboy login:** [ 1541.103019] GPIO_IN=08
[ 1541.103090] @@@@- #2  rtw_ps_processor==> rfstate:rf_on
[ 1543.103030] GPIO_IN=08
[ 1543.103093] @@@@- #2  rtw_ps_processor==> rfstate:rf_on
[ 1545.103027] GPIO_IN=08
[ 1545.103091] @@@@- #2  rtw_ps_processor==> rfstate:rf_on
[ 1547.103048] GPIO_IN=08
[ 1547.103111] @@@@- #2  rtw_ps_processor==> rfstate:rf_on
[ 1549.103051] GPIO_IN=08
[ 1549.103109] @@@@- #2  rtw_ps_processor==> rfstate:rf_on
[ 1551.103050] GPIO_IN=08
[ 1551.103111] @@@@- #2  rtw_ps_processor==> rfstate:rf_on
[ 1553.103058] GPIO_IN=08
[ 1553.103116] @@@@- #2  rtw_ps_processor==> rfstate:rf_on
[ 1555.103012] GPIO_IN=08
[ 1555.103079] @@@@- #2  rtw_ps_processor==> rfstate:rf_on
[ 1557.103022] GPIO_IN=08
[ 1557.106445] @@@@- #2  rtw_ps_processor==> rfstate:rf_on

This doesn’t happen in the Jessie or Wheezy Raspbian images. I overwrote my only SD card to install OSMC or I’d compare modules and what-not.

The first instance of this error in dmesg appears here:

 9.076217] Set SSID under fw_state=0x00000008
[    9.076241] <=rtw_wx_set_essid, ret 0
[    9.163190] [rtw_wx_set_pmkid] IW_PMKSA_FLUSH!
[   10.238141] survey done event(26) band:0 for wlan0
[   10.272848] rtw_select_and_join_from_scanned_queue: return _FAIL(candidate == NULL)
[   10.304811] try_to_join, but select scanning queue fail, to_roaming:0
[   10.713282] GPIO_IN=08
**[   10.746603] @@@@- #2  rtw_ps_processor==> rfstate:rf_on**
**[   11.114813] wpa_set_auth_algs, AUTH_ALG_OPEN_SYSTEM**
[   11.147536] set_mode = IW_MODE_INFRA

I imagine the problem is coming from this guy:

modinfo 8192cu
filename: /lib/modules/4.2.1-1-osmc/kernel/drivers/net/wireless/8192cu.ko
version: v4.0.2_9000.20130911
author: Realtek Semiconductor Corp.
description: Realtek Wireless Lan Driver

It seems so strange that a GPIO message is always accompanied by a rtw_ps_processor message…

bryan_martin · 3 October 2015 07:18

It looks like they left some debugging messages in this driver. Was it compiled with debug messaging enabled or something?

The GPIO line is happening here:

github.com

torvalds/linux/blob/dd5cdb48edfd34401799056a9acf61078d773f90/drivers/net/wireless/rtlwifi/rtl8192cu/hw.c#L2257


      
          					       ERFOFF : ERFON;
          			RT_TRACE(rtlpriv, COMP_POWER, DBG_DMESG,
          				 "pwrdown, 0x5c(BIT7)=%02x\n", u1tmp);
          		} else {
          			rtl_write_byte(rtlpriv, REG_MAC_PINMUX_CFG,
          				       rtl_read_byte(rtlpriv,
          				       REG_MAC_PINMUX_CFG) & ~(BIT(3)));
          			u1tmp = rtl_read_byte(rtlpriv, REG_GPIO_IO_SEL);
          			e_rfpowerstate_toset  = (u1tmp & BIT(3)) ?
          						 ERFON : ERFOFF;
          			RT_TRACE(rtlpriv, COMP_POWER, DBG_DMESG,
          				 "GPIO_IN=%02x\n", u1tmp);
          		}
          		RT_TRACE(rtlpriv, COMP_POWER, DBG_LOUD, "N-SS RF =%x\n",
          			 e_rfpowerstate_toset);
          	}
          	if ((ppsc->hwradiooff) && (e_rfpowerstate_toset == ERFON)) {
          		RT_TRACE(rtlpriv, COMP_POWER, DBG_LOUD,
          			 "GPIOChangeRF  - HW Radio ON, RF ON\n");
          		ppsc->hwradiooff = false;
          		actuallyset = true;

bryan_martin · 3 October 2015 07:19

And the other entry is happening here:

github.com

torvalds/linux/blob/9c6a019c6edf8591e34ae9da51bac7684131d905/drivers/staging/rtl8188eu/core/rtw_pwrctrl.c#L251


      
          	struct mlme_priv *pmlmepriv = &(padapter->mlmepriv);
          	enum rt_rf_power_state rfpwrstate;
          
          
	pwrpriv->ps_processing = true;
          
          
	if (pwrpriv->bips_processing)
          		goto exit;
          
          
	if (padapter->pwrctrlpriv.bHWPwrPindetect) {
          		rfpwrstate = RfOnOffDetect(padapter);
          		DBG_88E("@@@@- #2  %s==> rfstate:%s\n", __func__, (rfpwrstate == rf_on) ? "rf_on" : "rf_off");
          
          
		if (rfpwrstate != pwrpriv->rf_pwrstate) {
          			if (rfpwrstate == rf_off) {
          				pwrpriv->change_rfpwrstate = rf_off;
          				pwrpriv->brfoffbyhw = true;
          				rtw_hw_suspend(padapter);
          			} else {
          				pwrpriv->change_rfpwrstate = rf_on;
          				rtw_hw_resume(padapter);
          			}

Looks like it tries this power check stuff every 2 seconds:

/drivers/staging/rtl8188eu/include/rtw_pwrctrl.h
#define RTW_PWR_STATE_CHK_INTERVAL 2000

So that explains why we’re getting flooded with these messages.

lsusb output:
Bus 001 Device 004: ID 7392:7811 Edimax Technology Co., Ltd EW-7811Un 802.11n Wireless Adapter [Realtek RTL8188CUS]

I’d try setting this to ‘n’ next time you build the osmc wifi modules.

config RTLWIFI_DEBUG
bool “Debugging output for rtlwifi driver family”
depends on RTLWIFI
default y
—help—
To use the module option that sets the dynamic-debugging level for,
the front-end driver, this parameter must be “Y”. For memory-limited
systems, choose “N”. If in doubt, choose “Y”.

(Sorry - had to split this into 2 messages because I wasn’t allowed multiple links in a post)

sam_nazarko · 3 October 2015 19:25

Hi

Thanks for the insight

I will check the kernel configuration and check whether debugging is indeed enabled. Please keep in mind that the RTL8192CU driver is not built in-tree, so this kernel configuration option shouldn’t make a difference. We’ve been building 8192CU out of tree since around March, so this change may have been introduced by the addition of power-pin detection. I will still need to work out why it’s affecting both in-tree (8188EU) and out of tree (8192cu / 8812au) devices.

Sam

Cristian_Ionescu_Idb · 25 October 2015 17:08

Linux osmc 4.2.3-2-osmc #1 SMP PREEMPT Mon Oct 12 01:58:40 UTC 2015 armv7l GNU/Linux
Bus 001 Device 004: ID 2001:3308 D-Link Corp. DWA-121 802.11n Wireless N 150 Pico Adapter [Realtek RTL8188CUS]

Setting interface down:

ip link set wlan0 down

is not enough. Spamming messages continue:

Oct 25 17:39:19 osmc kernel: @@@@- #2 rtw_ps_processor==> rfstate:rf_on
Oct 25 17:39:21 osmc kernel: GPIO_IN=08

Removing the 8192cu module creates silence:

rmmod 8192cu

but then one can’t use that interface then

Cheers,

–
Cristian

bryan_martin · 1 November 2015 18:31

This was not fixed in the October 25th update.

If you’re building these modules out of tree, then you probably need to disable that debugging in the makefile for the module or something like that. It must ignore the kernel config.

sam_nazarko · 1 November 2015 21:46

Hi Bryan,

I never said it was fixed in the October update. I still haven’t had time to look at this thoroughly yet, but what’s noteworthy is that is that users have reported that in tree modules are also affected. We don’t have a persistent journal, so this will not degrade performance at all.

I’ll address this when I get some time and refresh WiFi drivers for OSMC. i certainly see the RT_TRACE pr_info calls but not the reason this has suddenly changed. If you can spot anything in our repo that would be helpful.

Sam

sam_nazarko · 15 November 2015 16:52

I think this is caused by power pin detection.

Would anyone like to try a newer kernel with CONFIG_HW_PWRP=n?. Although, with that said 8188CUS is built in-tree, so I’m not sure if these symbols are being redefined or what exactly is causing this…

Sam

Mausy5043 · 16 November 2015 17:01

@sam_nazarko I’ll gladly do some tests for you. However, I’m out of the country for a couple of days. Won’t be able to test before 22NOV2015.
If that’s not a problem for you, just let me know how I can be of assistance.

sam_nazarko · 16 November 2015 23:39

Sounds good.

Edit /etc/apt/sources.list
Change deb http://apt.osmc.tv jessie main to deb http:/apt.osmc.tv jessie-devel main
Run sudo apt-get update
Run sudo apt-get install rbp1-kernel-osmc or sudo apt-get install rbp2-kernel-osmc
Change /etc/apt/apt/sources.list back to the original
Reboot.

Sam

wilsonalmeida · 20 November 2015 07:19

@sam_nazarko Hi, Just tried the new kernel as you suggested and the messages have stopped. Thank you

sam_nazarko · 20 November 2015 07:22

Thanks for confirming!

Sam

wilsonalmeida · 20 November 2015 07:36

@sam_nazarko All thanks to you for fixing this issue as it’s been irritating me since September and thought it was probably affecting the performance of my kodi box too

Mausy5043 · 21 November 2015 14:39

@sam_nazarko : I’ve tested with various dongles. I had to reinstall from the 01NOV2015 release of OSMC. Currently, I can’t reproduce the problem.

The odd thing is though that using the OSMC shop dongle now it is recognised as an Ralink dongle while previously (september) the same dongle was detected as Realtek. This confuses me a bit.
But given the fact things are up and running nicely I’m guessing it was all part of the problem.

Closing this issue. Feel free to re-open if needed.