kernel spams with useless messages (fbcon_event_notify action, etc.)

[lindi]

Even when I am not using the phone at all my logs get filled with kernel messages like

Apr  7 04:18:32 ginger kernel: [  289.015000] fbcon_event_notify action=9, data=c4609e08
Apr  7 04:18:32 ginger kernel: [  289.015000] jbt6k74 spi2.0: **** jbt6k74 powerdown
Apr  7 04:18:42 ginger kernel: [  299.090000] fbcon_event_notify action=9, data=c4609e08
Apr  7 04:18:42 ginger kernel: [  299.090000] jbt6k74 spi2.0: **** jbt6k74 powerdown
Apr  7 04:18:52 ginger kernel: [  309.160000] fbcon_event_notify action=9, data=c4609e08
Apr  7 04:18:52 ginger kernel: [  309.160000] jbt6k74 spi2.0: **** jbt6k74 powerdown
Apr  7 04:19:02 ginger kernel: [  319.235000] fbcon_event_notify action=9, data=c4609e08
Apr  7 04:19:02 ginger kernel: [  319.235000] jbt6k74 spi2.0: **** jbt6k74 powerdown
Apr  7 04:19:12 ginger kernel: [  329.310000] fbcon_event_notify action=9, data=c4609e08
Apr  7 04:19:12 ginger kernel: [  329.310000] jbt6k74 spi2.0: **** jbt6k74 powerdown
Apr  7 04:19:13 ginger kernel: [  330.445000] pcf50633 0-0073: INT1=0x80 INT2=0x00 INT3=0x10 INT4=0x00 INT5=0x00
Apr  7 04:19:14 ginger ogsmd.channel DEBUG    <MiscChannel via /dev/pts/0>: _readyToSend: watch timeout = None
Apr  7 04:19:14 ginger kernel: [  330.535000] pcf50633 0-0073: INT1=0x00 INT2=0x00 INT3=0x00 INT4=0x00 INT5=0x00
Apr  7 04:19:14 ginger ogsmd    DEBUG    (<MiscChannel via /dev/pts/0>: last communication with modem was 50 seconds ago. Sending EOF to wakeup)
Apr  7 04:19:14 ginger kernel: [  330.555000] pcf50633 0-0073: INT1=0x00 INT2=0x00 INT3=0x00 INT4=0x00 INT5=0x00
Apr  7 04:19:14 ginger kernel: [  330.715000] pcf50633 0-0073: INT1=0x00 INT2=0x00 INT3=0x20 INT4=0x00 INT5=0x00
Apr  7 04:19:14 ginger ogsmd.channel DEBUG    <MiscChannel via /dev/pts/0>: sending 9 bytes: 'AT+COPS?\r'
Apr  7 04:19:14 ginger kernel: [  330.800000] pcf50633 0-0073: INT1=0x00 INT2=0x00 INT3=0x00 INT4=0x00 INT5=0x00
Apr  7 04:19:14 ginger ogsmd.channel DEBUG    <MiscChannel via /dev/pts/0>: _readyToRead: watch timeout = 317
Apr  7 04:19:14 ginger ogsmd.channel DEBUG    <MiscChannel via /dev/pts/0>: got 28 bytes: '\r\n+COPS: 0,2,"24405"\r\n\r\nOK\r\n'
Apr  7 04:19:14 ginger kernel: [  330.845000] pcf50633 0-0073: INT1=0x00 INT2=0x00 INT3=0x00 INT4=0x00 INT5=0x00
Apr  7 04:19:14 ginger ogsmd.channel DEBUG    <MiscChannel via /dev/pts/0>: COMPLETED 'AT+COPS?' => ['+COPS: 0,2,"24405"', 'OK']
Apr  7 04:19:14 ginger ogsmd.channel DEBUG    <MiscChannel via /dev/pts/0>: _readyToSend: watch timeout = None

this wastes disk space and makes finding the important stuff from logs more difficult. Please consider making these debug prints something that can be configured at runtime if they are really needed.

(Ignore the ogsmd DEBUG messages, they are caused by my periodic watchdog that checks that the phone is connected to GSM network every 50 seconds.)

I am reporting this bug against andy-tracking b8b36e5ec3db71d5 which is quite old. Please close this if the bug has already been fixed in newer kernels. I'll try to move to newer kernels when bugs #2255 and #2257 have been resolved.

[arhuaco]

this wastes disk space and makes finding the important stuff from logs more difficult. Please consider making these debug prints something that can be configured at runtime if they are really needed.

I guess they are needed by kernel developers who can enable them anyway... Anyone against turning some of these messages off? They can be enabled at compile-time.

I'll try to move to newer kernels when bugs #2255 and #2257 have been resolved.

Good. At least you can count on #2255 being fixed soon.

[nicolas.dufresne]

JBT spam is already cleaned up. I'll fix fbcon.

[nicolas.dufresne]

Fix for ths issue (also sent to kernel mailing list)

[lindi]

Thanks. After these the only regular kernel messages I see are

03:09:33 INT1=0x80 INT2=0x00 INT3=0x01 INT4=0x00 INT5=0x00
03:09:33 INT1=0x00 INT2=0x00 INT3=0x00 INT4=0x00 INT5=0x00
03:09:33 INT1=0x00 INT2=0x00 INT3=0x00 INT4=0x00 INT5=0x00
03:24:33 Charging restarted..
03:34:57 INT1=0x80 INT2=0x00 INT3=0x01 INT4=0x00 INT5=0x00
03:34:58 INT1=0x00 INT2=0x00 INT3=0x00 INT4=0x00 INT5=0x00
03:34:58 INT1=0x00 INT2=0x00 INT3=0x00 INT4=0x00 INT5=0x00
03:49:57 Charging restarted..
04:00:39 INT1=0x80 INT2=0x00 INT3=0x01 INT4=0x00 INT5=0x00
04:00:39 INT1=0x80 INT2=0x00 INT3=0x00 INT4=0x00 INT5=0x00
04:00:39 INT1=0x00 INT2=0x00 INT3=0x00 INT4=0x00 INT5=0x00
04:15:39 Charging restarted..
04:25:40 INT1=0x80 INT2=0x00 INT3=0x01 INT4=0x00 INT5=0x00
04:25:40 INT1=0x80 INT2=0x00 INT3=0x00 INT4=0x00 INT5=0x00
04:25:40 INT1=0x00 INT2=0x00 INT3=0x00 INT4=0x00 INT5=0x00
04:40:40 Charging restarted..
04:49:43 INT1=0x80 INT2=0x00 INT3=0x01 INT4=0x00 INT5=0x00
04:49:43 INT1=0x00 INT2=0x00 INT3=0x00 INT4=0x00 INT5=0x00
04:49:43 INT1=0x00 INT2=0x00 INT3=0x00 INT4=0x00 INT5=0x00
05:04:43 Charging restarted..
05:14:43 INT1=0x80 INT2=0x00 INT3=0x01 INT4=0x00 INT5=0x00
05:14:43 INT1=0x00 INT2=0x00 INT3=0x00 INT4=0x00 INT5=0x00
05:14:43 INT1=0x00 INT2=0x00 INT3=0x00 INT4=0x00 INT5=0x00
05:29:43 Charging restarted..
05:39:36 INT1=0x80 INT2=0x00 INT3=0x01 INT4=0x00 INT5=0x00
05:39:36 INT1=0x00 INT2=0x00 INT3=0x00 INT4=0x00 INT5=0x00
05:39:36 INT1=0x00 INT2=0x00 INT3=0x00 INT4=0x00 INT5=0x00
05:54:36 Charging restarted..
06:05:54 INT1=0x80 INT2=0x00 INT3=0x01 INT4=0x00 INT5=0x00
06:05:54 INT1=0x00 INT2=0x00 INT3=0x00 INT4=0x00 INT5=0x00
06:05:54 INT1=0x00 INT2=0x00 INT3=0x00 INT4=0x00 INT5=0x00
}}

We probably don't want to get rid of "Charging restarted.."  but what are these interrupts?

[arhuaco]

Patch applied.

We probably don't want to get rid of "Charging restarted.." but what are these interrupts?

lindi: I'll open another bug with the information you just sent so that we can receive feedback in case someone actually cares about the messages.

[arhuaco]

Oh. Check #2237. Shall we really remove those "INT1=0x00 INT2=0x00"... messages? It seems in this case they were useful.

[nicolas.dufresne]

Note I have kept most of those traces, I've just moved them to proper log level. If you set loglevel to 8, they will reapear. We could do the same for the power management traces. Still I think they are counter intuitive and may need some rework. As this chip is really central to our machine it would be worth to have some string table to translate the information into human readable containt ?

[lindi]

Hard to say since I have not studied what interrupts those are.