736090 - Add timestamp to remote tests

Status: RESOLVED WONTFIX

(Testing :: Talos, defect)

Description

[Armen [:armenzg]]

It is very hard to know at what time each line was printed and it would be helpful to know in which order things happened and for how long they were hanging.

Could you please modify the logs so we can see the timestamps at the beginning of each line?

This would help for bugs like bug 719377 and other were things crash.

Comment 1

[Joel Maher ( :jmaher ) (UTC -8)]

could you please explain a bit more?  There are runtimes at the end of the unittest.  We also have to have uniform logs to match the logparsers.  Maybe there is a middle of the road approach here.

Comment 2

[Armen [:armenzg]]

For instance, on the following output I can't tell how much time passed from:
"INFO | automation.py | Application pid: 1715"
to
"DeviceManager: error pulling file '/mnt/sdcard/tests/reftest/reftest.log': No such file or directory"
to
"INFO | automation.py | Application ran for: 1:01:18.801008"

Perhaps, all we really need is a way to catch crashes earlier.
It seems that without being able to retrieve the log we fail to go and seek the minidumps.

Not sure if the timestamp would help at the beginning of each line.

What do you think? I am fine closing this one for another bug.

unable to execute ADB: ensure Android SDK is installed and adb is in your $PATH
restarting as root failed
reconnecting socket
args: ['../hostutils/bin/xpcshell', '-g', '/builds/tegra-023/test/build/hostutils/xre', '-v', '170', '-f', '/builds/tegra-023/test/build/tests/reftest/reftest/components/httpd.js', '-e', "const _PROFILE_PATH = '/tmp/tmpzlEIhj';const _SERVER_PORT = '30023'; const _SERVER_ADDR ='10.250.48.200';", '-f', '/builds/tegra-023/test/build/tests/reftest/server.js']
INFO | remotereftests.py | Server pid: 68543
pushing directory: /tmp/tmp3rOD3I to /mnt/sdcard/tests/reftest/profile
pushing directory: /tmp/tmp3rOD3I to /mnt/sdcard/tests/reftest/profile
REFTEST INFO | runreftest.py | Running tests: start.

FIRE PROC: '"MOZ_CRASHREPORTER=1,XPCOM_DEBUG_BREAK=stack,MOZ_CRASHREPORTER_NO_REPORT=1,NO_EM_RESTART=1,MOZ_PROCESS_LOG=/tmp/tmp_f7qYKpidlog,XPCOM_MEM_BLOAT_LOG=/tmp/tmp3rOD3I/runreftest_leaks.log" org.mozilla.fennec -no-remote -profile /mnt/sdcard/tests/reftest/profile/'
INFO | automation.py | Application pid: 1715
DeviceManager: error pulling file '/mnt/sdcard/tests/reftest/reftest.log': No such file or directory
DeviceManager: error pulling file '/mnt/sdcard/tests/reftest/reftest.log': No such file or directory
DeviceManager: error pulling file '/mnt/sdcard/tests/reftest/reftest.log': No such file or directory
...
DeviceManager: error pulling file '/mnt/sdcard/tests/reftest/reftest.log': No such file or directory

INFO | automation.py | Application ran for: 1:01:18.801008
INFO | automation.py | Reading PID log: /tmp/tmp_f7qYKpidlog
getting files in '/mnt/sdcard/tests/reftest/profile/minidumps/'
WARNING | automationutils.processLeakLog() | refcount logging is off, so leaks can't be detected!

REFTEST INFO | runreftest.py | Running tests: end.
DeviceManager: error pulling file '/mnt/sdcard/tests/reftest/reftest.log': No such file or directory
program finished with exit code 0
elapsedTime=3698.774100

Comment 3

[Joel Maher ( :jmaher ) (UTC -8)]

so we could put timestamps on messages coming from devicemanager.  That might be the best solution.  In reality I don't think it will shed any light.  It might speed up discovery of a bottleneck.   What means a lot to me are these two lines:
INFO | automation.py | Application ran for: 1:01:18.801008
elapsedTime=3698.774100

When I see that with no other output, then fennec didn't start properly.

Comment 4

[Joel Maher ( :jmaher ) (UTC -8)]

moving the remaining android talos tests to autophone this quarter, autophone is more robust in device management and retrying, most likely we will not see this issue there.