cip/linux-4.4.y-cip usb: 4 runs, 2 regressions (v4.4.243-cip51-21-g1d9a9094c010)
Regressions Summary -------------------
platform | arch | lab | compiler | defconfig | regressions ------------------+------+---------------+----------+--------------------+------------ rk3288-veyron-jaq | arm | lab-collabora | gcc-8 | multi_v7_defconfig | 2
Details: https://kernelci.org/test/job/cip/branch/linux-4.4.y-cip/kernel/v4.4.243-cip...
Test: usb Tree: cip Branch: linux-4.4.y-cip Describe: v4.4.243-cip51-21-g1d9a9094c010 URL: https://git.kernel.org/pub/scm/linux/kernel/git/cip/linux-cip.git SHA: 1d9a9094c01054b624cd936e8b130a2c27e38c49
Test Regressions ----------------
platform | arch | lab | compiler | defconfig | regressions ------------------+------+---------------+----------+--------------------+------------ rk3288-veyron-jaq | arm | lab-collabora | gcc-8 | multi_v7_defconfig | 2
Details: https://kernelci.org/test/plan/id/5fc871ebf573faf8a4c94cc7
Results: 2 PASS, 2 FAIL, 0 SKIP Full config: multi_v7_defconfig Compiler: gcc-8 (arm-linux-gnueabihf-gcc (Debian 8.3.0-2) 8.3.0) Plain log: https://storage.kernelci.org//cip/linux-4.4.y-cip/v4.4.243-cip51-21-g1d9a909... HTML log: https://storage.kernelci.org//cip/linux-4.4.y-cip/v4.4.243-cip51-21-g1d9a909... Rootfs: http://storage.kernelci.org/images/rootfs/debian/buster/20201130.0/armhf/roo...
* usb.compare-freeze: https://kernelci.org/test/case/id/5fc871ebf573faf8a4c94cca new failure (last pass: v4.4.243-cip51-10-gd7466739b72e9)
2020-12-03 05:04:20.932000+00:00 + /usr/sbin/rtcwake -d rtc0 -m freeze -s 1 2020-12-03 05:04:20.932000+00:00 rtcwake: assuming RTC uses UTC ... 2020-12-03 05:04:20.937000+00:00 rtcwake: wakeup from "freeze" using rtc0 at Thu Dec 3 05:04:23 2020 2020-12-03 05:04:20.954000+00:00 [ 18.787404] PM: Syncing filesystems ... done. 2020-12-03 05:04:20.967000+00:00 [ 18.792542] Freezing user space processes ... (elapsed 0.001 seconds) done. 2020-12-03 05:04:20.968000+00:00 [ 18.800704] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done. 2020-12-03 05:04:20.972000+00:00 [ 18.809224] Suspending console(s) (use no_console_suspend to debug) 2020-12-03 05:04:23.674000+00:00 [ 18.865290] hub 3-1:1.0: activate --> -113 2020-12-03 05:04:23.675000+00:00 [ 18.867538] PM: suspend of devices complete after 51.550 msecs 2020-12-03 05:04:23.685000+00:00 [ 18.868293] PM: late suspend of devices complete after 0.750 msecs ... (66 line(s) more)
* usb.compare-mem: https://kernelci.org/test/case/id/5fc871ebf573faf8a4c94ccb new failure (last pass: v4.4.243-cip51-10-gd7466739b72e9)
2020-12-03 05:04:30.020000+00:00 02-14 10:12:11.459256544 +0000 2020-12-03 05:04:30.032000+00:00 @@ -1,4 +1,5 @@ 2020-12-03 05:04:30.032000+00:00 0424:9514 2020-12-03 05:04:30.032000+00:00 +0424:ec00 2020-12-03 05:04:30.032000+00:00 04f2:b443 2020-12-03 05:04:30.033000+00:00 1d6b:0002 2020-12-03 05:04:30.033000+00:00 1d6b:0002 2020-12-03 05:04:30.033000+00:00 + seq 1 3 2020-12-03 05:04:30.033000+00:00 + /usr/sbin/rtcwake -d rtc0 -m mem -s 1 2020-12-03 05:04:30.038000+00:00 rtcwake: assuming RTC uses UTC ... ... (89 line(s) more)
Hello, bot. Can you speak english?
cip/linux-4.4.y-cip usb: 4 runs, 2 regressions (v4.4.243-cip51-21-g1d9a9094c010)
usb.compare-freeze: https://kernelci.org/test/case/id/5fc871ebf573faf8a4c94cca new failure (last pass: v4.4.243-cip51-10-gd7466739b72e9)
2020-12-03 05:04:20.932000+00:00 + /usr/sbin/rtcwake -d rtc0 -m freeze -s 1 2020-12-03 05:04:20.932000+00:00 rtcwake: assuming RTC uses UTC ... 2020-12-03 05:04:20.937000+00:00 rtcwake: wakeup from "freeze" using rtc0 at Thu Dec 3 05:04:23 2020 2020-12-03 05:04:20.954000+00:00 [ 18.787404] PM: Syncing filesystems ... done. 2020-12-03 05:04:20.967000+00:00 [ 18.792542] Freezing user space processes ... (elapsed 0.001 seconds) done. 2020-12-03 05:04:20.968000+00:00 [ 18.800704] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done. 2020-12-03 05:04:20.972000+00:00 [ 18.809224] Suspending console(s) (use no_console_suspend to debug) 2020-12-03 05:04:23.674000+00:00 [ 18.865290] hub 3-1:1.0: activate --> -113 2020-12-03 05:04:23.675000+00:00 [ 18.867538] PM: suspend of devices complete after 51.550 msecs 2020-12-03 05:04:23.685000+00:00 [ 18.868293] PM: late suspend of devices complete after 0.750 msecs ... (66 line(s) more)
I'm not sure where you see failure here, plus I find it hard to believe that we have broken anything between v4.4.243-cip51-10-gd7466739b72e9 and v4.4.243-cip51-21-g1d9a9094c010.
Can you elaborate what is wrong, and maybe re-run tests with v4.4.243-cip51-10-gd7466739b72e9 to see if this is maybe some kind of random failure?
Best regards,
Pavel
Hello Pavel,
From: cip-dev@lists.cip-project.org cip-dev@lists.cip-project.org On Behalf Of Pavel Machek via lists.cip-project.org Sent: 04 December 2020 16:40
*** gpg4o | HINT: Error while checking message with detached signature (PGP/MIME signature)! Couldn't locate the original MIME source of the mail to verify the signature! gpg4oh32.dll:: func_IV Init OK ***
Hello, bot. Can you speak english?
Beep boop.
I've recently enabled these email reports. They come from KernelCI.org. I meant to say yesterday, but forgot :(
cip/linux-4.4.y-cip usb: 4 runs, 2 regressions (v4.4.243-cip51-21-
g1d9a9094c010)
* usb.compare-freeze:
https://jpn01.safelinks.protection.outlook.com/?url=https%3A%2F%2Fkerne lci.org%2Ftest%2Fcase%2Fid%2F5fc871ebf573faf8a4c94cca&data=04%7 C01%7Cchris.paterson2%40renesas.com%7C41794d29ba6043ec1c0508d89873 4870%7C53d82571da1947e49cb4625a166a4a2a%7C0%7C0%7C6374269681917 60690%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2l uMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C1000&sdata=nzJf3VqtNFu zMZzElil70%2BeuQ1CSeidKlM4LBLh%2Flt4%3D&reserved=0
new failure (last pass: v4.4.243-cip51-10-gd7466739b72e9)
2020-12-03 05:04:20.932000+00:00 + /usr/sbin/rtcwake -d rtc0 -m freeze -
s 1
2020-12-03 05:04:20.932000+00:00 rtcwake: assuming RTC uses UTC ... 2020-12-03 05:04:20.937000+00:00 rtcwake: wakeup from "freeze"
using rtc0 at Thu Dec 3 05:04:23 2020
2020-12-03 05:04:20.954000+00:00 [ 18.787404] PM: Syncing filesystems
... done.
2020-12-03 05:04:20.967000+00:00 [ 18.792542] Freezing user space
processes ... (elapsed 0.001 seconds) done.
2020-12-03 05:04:20.968000+00:00 [ 18.800704] Freezing remaining
freezable tasks ... (elapsed 0.001 seconds) done.
2020-12-03 05:04:20.972000+00:00 [ 18.809224] Suspending console(s)
(use no_console_suspend to debug)
2020-12-03 05:04:23.674000+00:00 [ 18.865290] hub 3-1:1.0: activate --> -
113
2020-12-03 05:04:23.675000+00:00 [ 18.867538] PM: suspend of devices
complete after 51.550 msecs
2020-12-03 05:04:23.685000+00:00 [ 18.868293] PM: late suspend of
devices complete after 0.750 msecs
... (66 line(s) more)
I'm not sure where you see failure here, plus I find it hard to believe that we have broken anything between v4.4.243-cip51-10-gd7466739b72e9 and v4.4.243-cip51-21-g1d9a9094c010.
Looking at the full test log [0] it looks like a comparison (before.txt with after-freeze.txt) has gone wrong. Presumably some corrupt data?
05:04:29.997473 + lava-test-case compare-freeze --shell diff -u before.txt after-f[ 27.830724] <LAVA_SIGNAL_STARTTC compare-freeze> 05:04:30.009142 reeze.txt 05:04:30.009390 --- before.txt[ 27.841181] <LAVA_SIGNAL_ENDTC compare-freeze> 05:04:30.009581 2019-02-14 10:12:01.895000001 +0000 05:04:30.020487 +++ after-freeze.txt 2019-[ 27.848337] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=compare-freeze RESULT=fail> 05:04:30.020750 02-14 10:12:11.459256544 +0000 05:04:30.032157 @@ -1,4 +1,5 @@ 05:04:30.032446 0424:9514 05:04:30.032634 +0424:ec00 05:04:30.032840 04f2:b443 05:04:30.033020 1d6b:0002 05:04:30.033195 1d6b:0002
[0] https://storage.kernelci.org/cip/linux-4.4.y-cip/v4.4.243-cip51-21-g1d9a9094...
Can you elaborate what is wrong, and maybe re-run tests with v4.4.243-cip51-10-gd7466739b72e9 to see if this is maybe some kind of random failure?
Perhaps random. I'm not sure how to trigger test re-runs through KernelCI.org. I'll ask if it's possible.
Kind regards, Chris
Best regards,
Pavel
DENX Software Engineering GmbH, Managing Director: Wolfgang Denk HRB 165235 Munich, Office: Kirchenstr.5, D-82194 Groebenzell, Germany
Hi!
*** gpg4o | HINT: Error while checking message with detached signature (PGP/MIME signature)! Couldn't locate the original MIME source of the mail to verify the signature! gpg4oh32.dll:: func_IV Init OK ***
Hello, bot. Can you speak english?
Beep boop.
I've recently enabled these email reports. They come from KernelCI.org. I meant to say yesterday, but forgot :(
No problem :-).
2020-12-03 05:04:20.968000+00:00 [ 18.800704] Freezing remaining
freezable tasks ... (elapsed 0.001 seconds) done.
2020-12-03 05:04:20.972000+00:00 [ 18.809224] Suspending console(s)
(use no_console_suspend to debug)
2020-12-03 05:04:23.674000+00:00 [ 18.865290] hub 3-1:1.0: activate --> -
113
2020-12-03 05:04:23.675000+00:00 [ 18.867538] PM: suspend of devices
complete after 51.550 msecs
2020-12-03 05:04:23.685000+00:00 [ 18.868293] PM: late suspend of
devices complete after 0.750 msecs
... (66 line(s) more)
I'm not sure where you see failure here, plus I find it hard to believe that we have broken anything between v4.4.243-cip51-10-gd7466739b72e9 and v4.4.243-cip51-21-g1d9a9094c010.
Looking at the full test log [0] it looks like a comparison (before.txt with after-freeze.txt) has gone wrong. Presumably some corrupt data?
05:04:29.997473 + lava-test-case compare-freeze --shell diff -u before.txt after-f[ 27.830724] <LAVA_SIGNAL_STARTTC compare-freeze> 05:04:30.009142 reeze.txt 05:04:30.009390 --- before.txt[ 27.841181] <LAVA_SIGNAL_ENDTC compare-freeze> 05:04:30.009581 2019-02-14 10:12:01.895000001 +0000 05:04:30.020487 +++ after-freeze.txt 2019-[ 27.848337] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=compare-freeze RESULT=fail> 05:04:30.020750 02-14 10:12:11.459256544 +0000 05:04:30.032157 @@ -1,4 +1,5 @@ 05:04:30.032446 0424:9514 05:04:30.032634 +0424:ec00 05:04:30.032840 04f2:b443 05:04:30.033020 1d6b:0002 05:04:30.033195 1d6b:0002
This looks like USB id's. (1d6b: is Linux foundation, common in USB hubs). So I believe this tells us that someone plugged in device 0424:ec00 -- ID 0424:ec00 Standard Microsystems Corp. SMSC9512/9514 Fast Ethernet Adapter ... and I don't think we have a bug to solve here.
Best regards,
Pavel
On 04/12/2020 17:48, Pavel Machek wrote:
Hi!
*** gpg4o | HINT: Error while checking message with detached signature (PGP/MIME signature)! Couldn't locate the original MIME source of the mail to verify the signature! gpg4oh32.dll:: func_IV Init OK ***
Hello, bot. Can you speak english?
Beep boop.
I've recently enabled these email reports. They come from KernelCI.org. I meant to say yesterday, but forgot :(
No problem :-).
2020-12-03 05:04:20.968000+00:00 [ 18.800704] Freezing remaining
freezable tasks ... (elapsed 0.001 seconds) done.
2020-12-03 05:04:20.972000+00:00 [ 18.809224] Suspending console(s)
(use no_console_suspend to debug)
2020-12-03 05:04:23.674000+00:00 [ 18.865290] hub 3-1:1.0: activate --> -
113
2020-12-03 05:04:23.675000+00:00 [ 18.867538] PM: suspend of devices
complete after 51.550 msecs
2020-12-03 05:04:23.685000+00:00 [ 18.868293] PM: late suspend of
devices complete after 0.750 msecs
... (66 line(s) more)
I'm not sure where you see failure here, plus I find it hard to believe that we have broken anything between v4.4.243-cip51-10-gd7466739b72e9 and v4.4.243-cip51-21-g1d9a9094c010.
Looking at the full test log [0] it looks like a comparison (before.txt with after-freeze.txt) has gone wrong. Presumably some corrupt data?
05:04:29.997473 + lava-test-case compare-freeze --shell diff -u before.txt after-f[ 27.830724] <LAVA_SIGNAL_STARTTC compare-freeze> 05:04:30.009142 reeze.txt 05:04:30.009390 --- before.txt[ 27.841181] <LAVA_SIGNAL_ENDTC compare-freeze> 05:04:30.009581 2019-02-14 10:12:01.895000001 +0000 05:04:30.020487 +++ after-freeze.txt 2019-[ 27.848337] <LAVA_SIGNAL_TESTCASE TEST_CASE_ID=compare-freeze RESULT=fail> 05:04:30.020750 02-14 10:12:11.459256544 +0000 05:04:30.032157 @@ -1,4 +1,5 @@ 05:04:30.032446 0424:9514 05:04:30.032634 +0424:ec00 05:04:30.032840 04f2:b443 05:04:30.033020 1d6b:0002 05:04:30.033195 1d6b:0002
This looks like USB id's. (1d6b: is Linux foundation, common in USB hubs). So I believe this tells us that someone plugged in device 0424:ec00 -- ID 0424:ec00 Standard Microsystems Corp. SMSC9512/9514 Fast Ethernet Adapter ... and I don't think we have a bug to solve here.
This test dumps all the USB vendor/product IDs in a text file before suspending the device, then does it again after resuming. It then compares them to see if all the USB devices came back from suspend. In this case, it looks like the USB-Ethernet adapter device failed. This may be an intermittent issue, or maybe it sometimes takes longer to resume and the test missed it after resume.
If this was a clear regression, an automated bisection would have most likely found the breaking commit. There hasn't been any, and since it's pretty unlikely anything between these 2 revisions broke anything it's most likely an unstable test result. It shouldn't be specific to the CIP kernel tree, let's see if we get the same problems in other kernel trees (stable, mainline, next). We may also adjust timing in the test if that is what is causing the problem. It's not a suspend/resume performance test.
Thanks, Guillaume
kernel-build-reports@lists.linaro.org
-
Chris Paterson -
Guillaume Tucker -
kernelci.org bot -
Pavel Machek