1422887 - AWFY - improve log handling

Status: RESOLVED WONTFIX

(Testing Graveyard :: AWFY, enhancement)

Description

[Bob Clary [:bc] (inactive)]

As part of the investigation for bug 1419524 we found that if the host hangs up, there is no means of diagnosing the cause (browser+suite) of the hang since the output is logged to memory before it is uploaded to the server. We decided in bug 1419524 to change the logging so that is is logged to a file which will be uploaded and deleted once the test result is submitted. If the host hangs, hopefully this will leave us with some clue as to what was running just prior to the hang.

Comment 1

[Bob Clary [:bc] (inactive)]

Attachment: https://github.com/mozilla/arewefastyet/pull/189

Change slave/run-task.sh to the standard run script. This will require:

- either ~/AWFY_CONFIG containing export CONTROL_UNIT_ID=id or
  CONTROL_UNIT_ID already in the environment.

- arewefastyet checked out to ~/arewefastyet

Once these conditions are met, start the script via

~/arewefastyet/slave/run-task.sh

Second, we change the print statements currently used to log to
stdout to use a set of functions which will continue to print to
stdout but also will log to a rotating log file controlled by the
main process. This log file will be shared by the main and child
processes but only the main process in task.py will be able to
rotate the log.

Lastly, we fix a number of pyflakes warnings though not all.

Comment 2

[Benjamin Bouvier [:bbouvier] (inactive)]

Comment on attachment 8940681 [details] [diff] [review]
https://github.com/mozilla/arewefastyet/pull/189

Review of attachment 8940681 [details] [diff] [review]:
-----------------------------------------------------------------

Looks good to me, thanks. I've added a few suggestions on Github, but it could be merged as is in the meanwhile.

Comment 3

[Bob Clary [:bc] (inactive)]

Comment on attachment 8940681 [details] [diff] [review]
https://github.com/mozilla/arewefastyet/pull/189

I've added additional commits to address your comments. If this meets with your approval, I'll squash before pushing.

Comment 4

[Bob Clary [:bc] (inactive)]

I updated the branch to set self.logger = logging.getLogger(self.__class__.__name__) in the base class then let the child classes inherit it which simplifies things a bit. Local testing looks good for this to work.

class Foo(object):
    def __init__(self):
        self.name = self.__class__.__name__

class Bar(Foo):
    pass

f = Foo()
b = Bar()

print f.name
print b.name

Comment 5

[Bob Clary [:bc] (inactive)]

https://github.com/mozilla/arewefastyet/commit/31efd4b7193b3250a58a2f3f1fc40ed2692513b8
https://github.com/mozilla/arewefastyet/commit/bf403354e59888fe4ade0187ecda542d030917b3
https://github.com/mozilla/arewefastyet/commit/a773d590c711edadc08ede8d90b985f75d085c7f

deploying now.

Comment 6

[Bob Clary [:bc] (inactive)]

I've standardized on ~/arewefastyet cloned from https://github.com/mozilla/arewefastyet, with awfy.config repos in the home directory.

Note there is a bug in slave/run-task.sh in that it will detect itself and declare run-task.sh is already running.

Comment 7

[Bob Clary [:bc] (inactive)]

Attachment: bug-1422887-v1.patch

ignore currently running process when checking for a running run-task.sh.

Comment 8

[Benjamin Bouvier [:bbouvier] (inactive)]

Comment on attachment 8941465 [details] [diff] [review]
bug-1422887-v1.patch

Review of attachment 8941465 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks

Comment 9

[Bob Clary [:bc] (inactive)]

Attachment: AWFY.log - NameError: global name 'benchmarks' is not defined

Well, the logging works sort of:

2018-01-10 08:21:58,376 - run_realtime - INFO -   File "server.py", line 43, in do_GET

2018-01-10 08:21:58,377 - run_realtime - INFO -     if self.remote_benchmark():

2018-01-10 08:21:58,377 - run_realtime - INFO -   File "server.py", line 157, in remote_benchmark

2018-01-10 08:21:58,378 - run_realtime - INFO -     protocol, url, path, version = self.translate_benchmark_path(host, self.path)

2018-01-10 08:21:58,378 - run_realtime - INFO -   File "server.py", line 140, in translate_benchmark_path

2018-01-10 08:21:58,379 - run_realtime - INFO -     for benchmark in benchmarks.Known:

2018-01-10 08:21:58,379 - run_realtime - INFO - NameError: global name 'benchmarks' is not defined

Need to trim the trailing new line from the logger message though not the print.

It seems my patch to server.py removed a needed import:
 
-import benchmarks_remote as benchmarks
-

Adding the import back in and running pyflakes shows:

$ pyflakes-2.7 server.py 
server.py:11: 'benchmarks_remote as benchmarks' imported but unused

https://github.com/mozilla/arewefastyet/commit/1f72436b08236bb6fc64c2a41311393ada98a84b

Strip trailing newlines from logger messages.
https://github.com/mozilla/arewefastyet/commit/0e28eca05420966b262f57125fbe480052dc3876

Comment 10

[Bob Clary [:bc] (inactive)]

Fix for the fact that the log messages are not always strings. Another r=self.
https://github.com/mozilla/arewefastyet/commit/0a6fcf764e898344828cb623e72a7c0b23382fa5

quantum is running...

Comment 11

[Bob Clary [:bc] (inactive)]

awfy-shells-macpro.corp.mtv2.mozilla.com required database edits to update the path to the repos in control_tasks and control_task_queue.

Windows machines required installation of pgrep.

Comment 12

[Bob Clary [:bc] (inactive)]

awfy-cmp-linux doesn't like the export DISPLAY=:0. Setting it to :1 does work however. I've locally changed run-task on awfy-cmp-linux to use DISPLAY=:1.

Is setting DISPLAY even necessary? If so, I think we should move it to AWFY_CONFIG.

Comment 13

[Benjamin Bouvier [:bbouvier] (inactive)]

Very strange, never heard of this issue before. Setting DISPLAY=1 on the Linux machine might be fine.

In unrelated news, v8/JSC don't update anymore on the shells machine, looking...

Comment 14

[Benjamin Bouvier [:bbouvier] (inactive)]

Pushed a trivial fix for webkit cloning: the repository was not present and incorrectly detected.
https://github.com/mozilla/arewefastyet/commit/ef82d3a8d324c0a9323c70e6d8dafd875c24752b

I'll look at v8 this afternoon; might be that their process changed, might be that the builder doesn't finish for some reason.

Comment 15

[Bob Clary [:bc] (inactive)]

I'll start looking.

control-task-recipe table in the db still included awfy-new in some of its tasks for the shell benchmarks. I've updated that and restarted on awfy-shells-macpro.

 Terminating the script on shells also gives:

^CTraceback (most recent call last):
  File "task.py", line 30, in <module>
    output = utils.run_realtime(task, shell=True)
  File "/Users/hannesverschore/arewefastyet/slave/utils.py", line 181, in run_realtime
    line = p.stdout.readline()
KeyboardInterrupt
/Users/.../arewefastyet/slave/run-task.sh: line 39: read: -i: invalid option
read: usage: read [-ers] [-u fd] [-t timeout] [-p prompt] [-a array] [-n nchars] [-d delim] [name ...]
Exiting....

Comment 16

[Bob Clary [:bc] (inactive)]

Attachment: 2018-01-10 shells errors

https://github.com/mozilla/arewefastyet/blob/master/slave/execute.py#L125

Comment 17

[Bob Clary [:bc] (inactive)]

Attachment: 2018-01-10 shells v8 errors

2018-01-11 05:18:35,670 - run_realtime - INFO - ________ running '/usr/bin/python v8/gypfiles/gyp_v8 --running-as-hook' in '/Users/hannesverschore/repos/v8-64'
2018-01-11 05:18:35,670 - run_realtime - INFO - GYP is now disabled by default in runhooks.

Comment 18

[Bob Clary [:bc] (inactive)]

calling this fixed.

Comment 19

[Bob Clary [:bc] (inactive)]

I reverted these changes due to bug 1433066

Comment 20

[Bob Clary [:bc] (inactive)]

and I'm not going to try again.