[tbot] How to debug acquire_linux

[Stefano Babic]

Hi Harald,

On 23/11/18 13:08, Harald Seiler wrote:
> Hi Stefano,
> 
> On Fri, 2018-11-23 at 13:04 +0100, Stefano Babic wrote:
>> On 23/11/18 12:32, Harald Seiler wrote:
>>> On Thu, 2018-11-22 at 19:24 +0100, Stefano Babic wrote:
>>>> Hi,
>>>>
>>>> I have a board that cannot be got in linux. It looks like that
>>>> tbot.acquire_linux() hangs forever (can I set a tiimeout ?)
>>>>
>>>> I ran a testcase that works fine for another board - I guess that the
>>>> issue is due to the fact that this board has a lot of output in part
>>>> caused by systemd and in part due to kernel messages that are printed to
>>>> the console. When I start the testcase, tbot remains in <board>-linux. I
>>>> can understand that board is up and works because software activates
>>>> some relays, but it is not recognized by tbot.
>>>>
>>>> The weird thing is that "interactive_linux" works.
>>>
>>> I overlooked this previously ... `interactive_linux` works?  That's not
>>> possible, it uses the *exact same* code-path ... Is this a consistent
>>> observation?
>>
>> That is was puzzle me. It worked - anyway, if I run 10 times the test
>> with login_wait=1 (or 2) as I had at the beginning, at least once
>> worked. So it seems there is a race, maybe because the shell (bash)
>> takes more time as you supposed.
>>
>> After I put login_wait=10, it works flawlessly.
>>
>>>
>>>> How can I debug this? 
>>>
>>> I pushed changes to the development branch that allow deeper introspection by showing
>>> all data sent and received ...
>>
>> Ok, I have installed it
> 
> Are you sure? The output still looks like the one from the old version ...
> Does `tbot --version` say "0.6.2-dev"?
> 

Sorry, my mistake - I tracked development, but I have not checked it
out. Now it is ok.

> If not, checkout the development branch locally, pull and run
> 
> 	python3 setup.py install --user
> 
> again please.
> 

It looks like that the additional traces change the time conditions. If
I run with -vvv works now, without not (in both cases login_wait=1

Anyway, the output with -vvv around the login is:


│   │    <>
│   ├─< 'GTU-0 login: '
│   ├─> 'root\n'
│   │    <> GTU-0 login: root
│   ├─> '\n'
│   ├─> "PROMPT_COMMAND=''\nPS1='TBOT-VEJPVC1QUk9NUFQK$ '\n"
│   ├─< 'root[   13.843245] NOHZ: local_softirq_pending 04\r\n[
13.847350] NOHZ: local_softirq_pending 04\r\n\r\r\n[   13.864221] NOHZ:
local_softirq_pending 04\r\n[   13.868323] NOHZ: local_softirq_pending
04\r\n[   13.872432] NOHZ: local_softirq_pending 286\r\n[   13.888457]
NOHZ: local_softirq_pending 80\r\n[   14.011121] NOHZ:
local_softirq_pending 04\r\n\x1b7\x1b[r\x1b[999;999H\x1b[6n'
│   ├─< '\x1b'
│   ├─< '8'
│   ├─< 'PROMPT_COMMAND='
│   ├─< "''\r\nPS1='TBOT-VE"
│   ├─< "JPVC1QUk9NUFQK$ '\r"
│   ├─< '\n'
│   ├─< 'root at GTU-0:~# '
│   ├─< "PROMPT_COMMAND=''"


But then works. In this case I see a kernel message (NOHZ:
local_softirq_pending) in between.

I run 4-5 times with -vvv, it works. The race is over with the traces :-(

Best regards,
Stefano


-- 
=====================================================================
DENX Software Engineering GmbH,      Managing Director: Wolfgang Denk
HRB 165235 Munich, Office: Kirchenstr.5, D-82194 Groebenzell, Germany
Phone: +49-8142-66989-53 Fax: +49-8142-66989-80 Email: sbabic at denx.de
=====================================================================