Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:18 as permitted sender) client-ip=2620:137:e000::1:18;
Date:   Mon, 2 May 2022 15:17:32 +0200
From:   Petr Mladek <pmladek@suse.com>
To:     Marek Szyprowski <m.szyprowski@samsung.com>
Cc:     John Ogness <john.ogness@linutronix.de>,
        Sergey Senozhatsky <senozhatsky@chromium.org>,
        Steven Rostedt <rostedt@goodmis.org>,
        Thomas Gleixner <tglx@linutronix.de>,
        linux-kernel@vger.kernel.org,
        Greg Kroah-Hartman <gregkh@linuxfoundation.org>,
        linux-amlogic@lists.infradead.org
Subject: Re: [PATCH printk v5 1/1] printk: extend console_lock for
 per-console locking
Message-ID: <Ym/Z7PYPqvWPEjuL@alley>
References: <Ymfgis0EAw0Oxoa5@alley>
 <Ymfwk+X0CHq6ex3s@alley>
 <CGME20220427070833eucas1p27a32ce7c41c0da26f05bd52155f0031c@eucas1p2.samsung.com>
 <2a82eae7-a256-f70c-fd82-4e510750906e@samsung.com>
 <Ymjy3rHRenba7r7R@alley>
 <b6c1a8ac-c691-a84d-d3a1-f99984d32f06@samsung.com>
 <87fslyv6y3.fsf@jogness.linutronix.de>
 <51dfc4a0-f6cf-092f-109f-a04eeb240655@samsung.com>
 <87k0b6blz2.fsf@jogness.linutronix.de>
 <32bba8f8-dec7-78aa-f2e5-f62928412eda@samsung.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <32bba8f8-dec7-78aa-f2e5-f62928412eda@samsung.com>
Precedence: bulk

On Mon 2022-05-02 11:19:07, Marek Szyprowski wrote:
> Hi John,
> 
> On 30.04.2022 18:00, John Ogness wrote:
> > On 2022-04-29, Marek Szyprowski <m.szyprowski@samsung.com> wrote:
> >> The same issue happens if I boot with init=/bin/bash
> > Very interesting. Since you are seeing all the output up until you try
> > doing something, I guess receiving UART data is triggering the issue.
> 
> Right, this is how it looks like.
> 
> >> I found something really interesting. When lockup happens, I'm still
> >> able to log via ssh and trigger any magic sysrq action via
> >> /proc/sysrq-trigger.
> > If you boot the system and directly login via ssh (without sending any
> > data via serial), can you trigger printk output on the UART? For
> > example, with:
> >
> >      echo hello > /dev/kmsg
> >
> > (You might need to increase your loglevel to see it.)
> 
> Data written to /dev/kmsg and all kernel logs were always displayed 
> correctly. Also data written directly to /dev/ttyAML0 is displayed 
> properly on the console. The latter doesn't however trigger the input 
> related activity.
> 
> It looks that the data read from the uart is delivered only if other 
> activity happens on the kernel console. If I type 'reboot' and press 
> enter, nothing happens immediately. If I type 'date >/dev/ttyAML0' via 
> ssh then, I only see the date printed on the console. However if I type 
> 'date >/dev/kmsg', the the date is printed and reboot happens.

This is really interesting.

'date >/dev/kmsg' should be handled like a normal printk().
It should get pushed to the console using printk kthread,
that calls call_console_driver() that calls con->write()
callback. In our case, it should be meson_serial_console_write().

I am not sure if meson_serial_console_write() is used also
when writing via /dev/ttyAML0.

> 
> >> It turned out that the UART console is somehow blocked, but it
> >> receives and buffers all the input. For example after issuing "echo
> >>   >/proc/sysrq-trigger" from the ssh console, the UART console has been
> >> updated and I see the magic sysrq banner and then all the commands I
> >> blindly typed in the UART console! However this doesn't unblock the
> >> console.
> > sysrq falls back to direct printing. This would imply that the kthread
> > printer is somehow unable to print.
> >
> >> Here is the output of 't' magic sys request:
> >>
> >> https://protect2.fireeye.com/v1/url?k=8649f24d-e73258c4-86487902-74fe48600034-a2ca6bb18361467d&q=1&e=1bc4226f-a422-42b9-95e8-128845b8609f&u=https%3A%2F%2Fpastebin.com%2FfjbRuy4f
> > It looks like the call trace for the printing kthread (pr/ttyAML0) is
> > corrupt.
> 
> Right, good catch. For comparison, here is a 't' sysrq result from the 
> 'working' serial console (next-20220429), which happens usually 1 of 4 
> boots:
> 
> https://pastebin.com/mp8zGFbW

Strange. The backtrace is weird here too:

[   50.514509] task:pr/ttyAML0      state:R  running task     stack:    0 pid:   65 ppid:     2 flags:0x00000008
[   50.514540] Call trace:
[   50.514548]  __switch_to+0xe8/0x160
[   50.514561]  meson_serial_console+0x78/0x118

There should be kthread() and printk_kthread_func() on the stack.

Hmm,  meson_serial_console+0x78/0x118 is weird on its own.
meson_serial_console is the name of the structure. I would
expect a name of the .write callback, like
meson_serial_console_write()

Best Regards,
Petr