Any ideas, paul?

Chris,

It's possible that the "not responding to signals" is a red herring and that was just a simple timeout.  It looks like the message is printed whenever "result_obj.exit_status is None".  I'm continuing to dig through the autotest code (though any ideas that Paul has would be appreciated, too).

I take it back--probably not a red herring.  I see now where it must be running: "bg_job.result.exit_status = bg_job.sp.poll()", so if that is None then it means that the process never exited.

...kinda curious where the 10 seconds comes from (from 13:35:44 to 13:35:54).  Maybe the process_output() or cleanup() functions in join_bg_jobs()?

In any case, you guys know this better than I.  ;)  We can also continue to see how often this happens, since this was only the first instance of this bug.  Maybe it's an isolated incident?

http://chromeos-botmaster.mtv.corp.google.com:8026/builders/stumpy-binary/builds/961/

10/25 15:14:13 DEBUG|base_utils:0081| Running '/usr/bin/python -c "import socket; print socket.gethostbyname('www.google.com.')"'
10/25 15:14:15 WARNI|base_utils:0819| run process timeout (2) fired on: /usr/bin/python -c "import socket; print socket.gethostbyname('www.google.com.')"
10/25 15:14:25 WARNI|cros_ui_te:0098| Command </usr/bin/python -c "import socket; print socket.gethostbyname('www.google.com.')"> failed and is not responding to signals, Command(s) did not complete within 2 seconds
* Command: 
    /usr/bin/python -c "import socket; print
    socket.gethostbyname('www.google.com.')"
Exit status: None
Duration: 12.0145931244

10/25 15:14:25 DEBUG|cros_ui_te:0107| Resolve attempt for www.google.com. got None
10/25 15:14:25 ERROR|site_utils:0078| Timed out waiting to revert DNS.

The magic 10s comes from the usage of nuke_subprocess() to kill the resolution attempt, which uses signal_pid():


def signal_pid(pid, sig):
    """
    Sends a signal to a process id. Returns True if the process terminated
    successfully, False otherwise.
    """
    try:
        os.kill(pid, sig)
    except OSError:
        # The process may have died before we could kill it.
        pass

    for i in range(5):
        if not pid_is_alive(pid):
            return True
        time.sleep(1)

    # The process is still alive
    return False


So, it sends 5 SIGTERMs and 5 SIGKILLs, at a rate of 1 per second.  Hence, 10.  So that's good to know.  It's also good to know that this process is apparently not listening to SIGKILL.

Commit: f85c56e9b4d22becc658c84bc17fb8770a3578a6
 Email: cmasone@chromium.org

[autotest] On DNS revert timeout, grab kernel stack of resolver process

It seems that these DNS timeouts are the result of the resolver process
we use getting stuck down in the kernel, as evidenced by the fact that
they will not respond to SIGKILL.

Add some temporary logging to grab the pid of the process and log the
kernel stack.

BUG=chromium-os:22019
TEST=manual; add a process that sleeps for 5s and use __log_kernel_stack('time.sleep') to get its info

Change-Id: I43ea1a09170ca66fdaa6715f7257dab036f0c415
Reviewed-on: https://gerrit.chromium.org/gerrit/10797
Commit-Ready: Chris Masone <cmasone@chromium.org>
Tested-by: Chris Masone <cmasone@chromium.org>
Reviewed-by: Paul Stewart <pstew@chromium.org>

M	client/cros/cros_ui_test.py

http://build.chromium.org/buildbot/chromiumos/builders/x86%20pineview%20full/builds/670

And, sadly, we weren't able to find the process and get a kernel stack trace.  I'll talk to scottz and see if I can find a way to instrument the autotest command-running code directly.

Commit: fa5dbf681d63e8787bf00c4aa86871c3ea0a00bd
 Email: cmasone@chromium.org

[autotest] Move kernel stack logging down into utils

Instead of trying to use shell commands to find the pid
of the unkillable process whose stack we want to dump,
just instrument the code down in common_lib/base_utils.py

BUG=chromium-os:22019
TEST=suite_Smoke should still run

Change-Id: I74256a63ad74b811548b964e8f845ea05b0d2772
Reviewed-on: https://gerrit.chromium.org/gerrit/11087
Reviewed-by: Scott Zawalski <scottz@chromium.org>
Commit-Ready: Chris Masone <cmasone@chromium.org>
Tested-by: Chris Masone <cmasone@chromium.org>

M	client/common_lib/base_utils.py
M	client/cros/cros_ui_test.py

This is marked as a TreeCloser. Please confirm that it should be a TreeCloser or remove the label. Please reassign as necessary.

This happens rather infrequently now; hoping the logging can catch it in the act.

Wontfix as these don't seem to happen often enough to worry about.

Commit: d4e72c40c906ae602a0979fc3c8db6bf720a6a54
 Email: cmasone@chromium.org

[autotest] Remove obsolete TODO()

To help diagnose http://crosbug.com/22019, we added some kernel stack
logging code on failed process kill.  We actually think that's a good
idea, so we decided to leave it and just take out the TODO telling us
to remove it.

BUG=chromium-os:22019
TEST=suite:bvt should still run

Change-Id: Ibfce0a05009c007fb5c833ae88150ea845978600
Reviewed-on: https://gerrit.chromium.org/gerrit/22611
Tested-by: Chris Masone <cmasone@chromium.org>
Reviewed-by: Scott Zawalski <scottz@chromium.org>
Commit-Ready: Chris Masone <cmasone@chromium.org>

M	client/common_lib/base_utils.py

Looks like we're hitting this bug again, reopening.

http://chromegw/i/chromeos/builders/mario%20incremental/builds/7137

We have a different kernel and a different connection manager now.  The odds that this is the same bug is pretty small.  Please don't re-open really old bugs because of similar surface symptoms.

Please open a new bug and start a new investigation.

(No comment was entered for this change.)

(No comment was entered for this change.)