Add test case logs URL #207

touilkhouloud · 2020-01-28T11:37:03Z

No description provided.

gctucker

Please fix the issues reported by Travis CI.

Also this caused an exception in the backend on staging:

Jan 28 21:41:05 kernelci-staging kernelci-celery[65490]:   File "/srv/api.staging.kernelci.org/app/utils/lava_log_parser.py", line 151, in run
Jan 28 21:41:05 kernelci-staging kernelci-celery[65490]:     log_buffer.append(sl + timestamp + fmt.format(cgi.escape(msg)) + el)
Jan 28 21:41:05 kernelci-staging kernelci-celery[65490]: AttributeError: 'NoneType' object has no attribute 'format'

touilkhouloud · 2020-01-29T09:17:46Z

Hello @gctucker, I fixed what you told me about, but there is something else must be fixed I guess that I am not able to determine from the CI build, do you have an idea about what fails ?

gctucker · 2020-01-29T13:08:34Z

@touilkhouloud You need to find the detailed log from the Travis CI job to see the errors:
https://travis-ci.com/kernelci/kernelci-backend/builds/146554824

These are simple unit test failures, because you're adding a new field to the test case document. You can reproduce the failures locally this way:

cd kernelci-backend/app
python -m unittest models.tests.test_test_case_model

I think you should just need to add some values with your new field there to make it pass.

touilkhouloud · 2020-01-31T09:11:49Z

@gctucker Hello, is everything fine or I need to change something else ?

gctucker · 2020-01-31T14:11:24Z

Thanks for fixing the issues, I'm starting another round of tests on staging to verify it.

khilman · 2020-02-13T00:41:54Z

I tried this in a fresh, local instance of kernelci-docker[0] (using staging branch of both frontend and backend). I then ran a baseline test via LAVA[1] which submitted results via the callback.

Looking in the database, I see that test_case_log_line field is created for all the test cases, but they are all null.

Is there a LAVA patch needed to send the log lines in the callback data?

[0] http://khilman.ddns.net:8080/
[1] http://lava-baylibre.baylibre:10080/scheduler/job/672148

touilkhouloud · 2020-02-13T08:29:58Z

Hello, I had a look on your json file and the problem is there I don't know why the log_start_line is empty, it's coming from LAVA like this you need to check that problem.

[0] http://khilman.ddns.net:8082/mainline/integ/v5.5-41-g19d85eebd7d6/arm64/defconfig/gcc-8/lab-baylibre/lava-json-meson-g12b-odroid-n2.json

mgalka · 2020-02-14T14:19:45Z

Hello, I had a look on your json file and the problem is there I don't know why the log_start_line is empty, it's coming from LAVA like this you need to check that problem.

[0] http://khilman.ddns.net:8082/mainline/integ/v5.5-41-g19d85eebd7d6/arm64/defconfig/gcc-8/lab-baylibre/lava-json-meson-g12b-odroid-n2.json

@touilkhouloud I had a look at a LAVA callback JSON provided by @khilman and it looks that it lacks line numbers in the "lava" test cases which is completely normal, but in the "real" test case 0_usb it does have both the log_start_line and the log_end_line.

'0_usb': "- id: '9542600'\n"
          "  job: '672428'\n"
          "  level: ''\n"
          "  log_end_line: '1007'\n"
          "  log_start_line: '1006'\n"
          "  logged: '2020-02-13 01:05:57.308205+00:00'\n"
          '  measurement: None\n'
          '  metadata: {case: usb-presence, definition: 0_usb, result: pass}\n'
          '  name: usb-presence\n'
          '  result: pass\n'
          '  suite: 0_usb\n'
          "  unit: ''\n"
          '  url: /results/testcase/9542600\n'

I guess that the reason of those not being stored is different. I went through the code of this PR and it seems to me that it extends the test_case document model with a field to store the line number, but it doesn't provide necessary LAVA callback handling to put there the actual value.
I created a PR #214 which extracts the line number from the LAVA callback JSON as well as it tries to match log fragments associated with a particular test case and store them in a test case document in Mongo.

My proposal is to merge this PR as it extends the model and adds links in the HTML log, then rebase the #214 on top of it and merge. I mentioned it already in the comment under #214. @khilman @gctucker What do you think of that?

gctucker · 2020-02-14T19:42:18Z

I think we should have a first PR that just adds IDs to the HTML log file so we can have anchored links to them. That way we can get this part merged quicker. It would also mean having the correct line numbers that work for the log povided by KernelCI as opposed to the one provided by LAVA which has extra LAVA-specific debugging information.

Then as a follow-up PR we can have the new field in the test case document and the LAVA callback logic to populate it.

gctucker · 2020-02-17T16:28:36Z

@touilkhouloud Could you please make a PR with just the first patch Add line numbers to the HTML log file? It will then be easier to merge it and review the rest of the changes in this PR separately.

touilkhouloud · 2020-02-18T15:23:15Z

@gctucker you can find the PR in #216 !

khilman

LGTM. My only minor nit is around terminology. In the patch from @mgalka, "log_line" is used for a line of log text, and here "log_line" is used for a line number. Maybe using log_line_num here would help clarify the difference?

@gctucker ?

In the test email report, each failing test will have a link to its logs in the html log file which is stored in the KernelCI data base. For that, we need to store the log line from the LAVA callback, adding this data to the data base and using it to generate the log url for each failing test case. Signed-off-by: Khouloud Touil <ktouil@baylibre.com>

touilkhouloud · 2020-04-14T15:54:42Z

Hello, @gctucker please can you have a look on this PR ?

gctucker

A few more things to week, #214 should be merged today or tomorrow so it can be used as a basis now.

gctucker · 2020-04-16T15:01:45Z

app/models/__init__.py

@@ -175,6 +175,7 @@
 SYSTEM_MAP_SIZE_KEY = "system_map_size"
 TEST_CASE_ID_KEY = "test_case_id"
 TEST_CASE_PATH_KEY = "test_case_path"
+TEST_CASE_LOG_LINE_KEY = "test_case_log_line"


Please rename to LOG_LINE_NUMBER_KEY, as log lines are actual lines from the log. The new field you're adding is intended to be a line number. Also I don't think we need to call it TEST_CASE_LOG_LINE_NUMBER_KEY since this could be used in theory in other places where a log line number is needed.

gctucker · 2020-04-16T15:03:00Z

app/models/test_case.py

@@ -57,6 +57,7 @@ def __init__(self, name, version="1.0"):
        self._measurements = []
        self._status = None
        self._test_group_id = None
+        self._test_case_log_line = None


Similarly, please change to self._log_line_number.

gctucker · 2020-04-16T15:04:01Z

app/utils/callback/lava.py

@@ -480,6 +480,9 @@ def _add_test_results(group, results):
        reference = test_meta.get("reference")
        if reference:
            test_case[models.ATTACHMENTS_KEY] = [reference]
+        test_case_log_line = test.get("log_start_line")


Please rebase on top of #214 as it works out the line numbers. In spite of its name, log_start_line is not actually the line number where the test case started.

gctucker · 2020-04-16T15:15:55Z

app/utils/report/templates/test.txt

@@ -60,6 +60,9 @@ Test Failures
      {%- for tc in group.test_cases %}
        {%- if 'FAIL' == tc.status %}
    * {{ tc.name }}:
+      {%- if tc.test_case_log_line %}
+        Test case HTML log: {{ storage_url }}/{{ group.file_server_resource }}/{{ group.lab_name }}/{{ group.boot_log_html }}#L{{ tc.test_case_log_line }}


I believe the line number stored from the LAVA meta-data is not going to match what is in the HTML log, because some lines are removed (LAVA debug...). For similar reasons, the line numbers will be different in the HTML and plain text log files. So I think we need to be more specific and maybe call this field html_log_line_number, and translate the line numbers when creating the HTML log file.

in the #216 when added the line number in the html file, I am doing in the way to add the number as close as possible to the lava callback log, if you didn't understand what I mean, see this link view-source:https://storage.staging.kernelci.org//kernelci/staging.kernelci.org/staging-20200421.0/arm/multi_v7_defconfig/gcc-8/lab-collabora/sleep-imx6q-sabrelite.html
you find for example line 8(L8) then 10(L10) but not line 9(L9).
Even if it's not the exact start line but in the exact logs, so I guess it's enough no ?
@gctucker @khilman

Well I think it's a bug that some log line numbers are missing in the output HTML log to start with. The numbers should be based in the HTML log, not where they came from.

Then the log line numbers stored in the test case should match exactly the line numbers in the HTML log.

All this data is known and handled by the backend code so it should only be a matter of fixing the logic.

touilkhouloud requested review from gctucker and khilman January 28, 2020 11:37

gctucker requested a review from a team January 28, 2020 17:00

gctucker added this to In Progress in KernelCI project board via automation Jan 28, 2020

gctucker added the staging-skip Don't test automatically on staging.kernelci.org label Jan 28, 2020

gctucker requested changes Jan 28, 2020

View reviewed changes

touilkhouloud force-pushed the add-logs-url branch from ffdbb57 to fe59bf3 Compare January 29, 2020 08:47

touilkhouloud force-pushed the add-logs-url branch 3 times, most recently from 2061abe to ec6b5f7 Compare January 29, 2020 14:08

gctucker removed the staging-skip Don't test automatically on staging.kernelci.org label Jan 31, 2020

touilkhouloud mentioned this pull request Feb 14, 2020

Add test related LAVA log fragment to the test case document #214

Merged

gctucker added the staging-skip Don't test automatically on staging.kernelci.org label Feb 19, 2020

touilkhouloud force-pushed the add-logs-url branch from ec6b5f7 to 0ddff45 Compare March 25, 2020 15:34

khilman removed the staging-skip Don't test automatically on staging.kernelci.org label Mar 25, 2020

touilkhouloud force-pushed the add-logs-url branch from 0ddff45 to 3534863 Compare March 25, 2020 18:21

touilkhouloud force-pushed the add-logs-url branch 3 times, most recently from e8e1435 to fd1ac36 Compare April 2, 2020 16:50

khilman reviewed Apr 2, 2020

View reviewed changes

touilkhouloud force-pushed the add-logs-url branch from fd1ac36 to 8306ddb Compare April 2, 2020 19:40

touilkhouloud force-pushed the add-logs-url branch from 8306ddb to adb6b85 Compare April 3, 2020 13:24

gctucker reviewed Apr 16, 2020

View reviewed changes

khilman mentioned this pull request Apr 30, 2020

Add log lines to the test report for the failed test cases #235

Merged

Base automatically changed from master to main January 12, 2021 21:49

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add test case logs URL #207

Add test case logs URL #207

touilkhouloud commented Jan 28, 2020

gctucker left a comment

touilkhouloud commented Jan 29, 2020 •

edited

gctucker commented Jan 29, 2020

touilkhouloud commented Jan 31, 2020

gctucker commented Jan 31, 2020

khilman commented Feb 13, 2020

touilkhouloud commented Feb 13, 2020

mgalka commented Feb 14, 2020

gctucker commented Feb 14, 2020

gctucker commented Feb 17, 2020

touilkhouloud commented Feb 18, 2020 •

edited

khilman left a comment

touilkhouloud commented Apr 14, 2020

gctucker left a comment

gctucker Apr 16, 2020

gctucker Apr 16, 2020

gctucker Apr 16, 2020

gctucker Apr 16, 2020

touilkhouloud Apr 21, 2020

gctucker May 1, 2020

Add test case logs URL #207

Are you sure you want to change the base?

Add test case logs URL #207

Conversation

touilkhouloud commented Jan 28, 2020

gctucker left a comment

Choose a reason for hiding this comment

touilkhouloud commented Jan 29, 2020 • edited

gctucker commented Jan 29, 2020

touilkhouloud commented Jan 31, 2020

gctucker commented Jan 31, 2020

khilman commented Feb 13, 2020

touilkhouloud commented Feb 13, 2020

mgalka commented Feb 14, 2020

gctucker commented Feb 14, 2020

gctucker commented Feb 17, 2020

touilkhouloud commented Feb 18, 2020 • edited

khilman left a comment

Choose a reason for hiding this comment

touilkhouloud commented Apr 14, 2020

gctucker left a comment

Choose a reason for hiding this comment

gctucker Apr 16, 2020

Choose a reason for hiding this comment

gctucker Apr 16, 2020

Choose a reason for hiding this comment

gctucker Apr 16, 2020

Choose a reason for hiding this comment

gctucker Apr 16, 2020

Choose a reason for hiding this comment

touilkhouloud Apr 21, 2020

Choose a reason for hiding this comment

gctucker May 1, 2020

Choose a reason for hiding this comment

touilkhouloud commented Jan 29, 2020 •

edited

touilkhouloud commented Feb 18, 2020 •

edited