nightly-qa-skeleton (building master-next) failed the oeqa.runtime.dmesg.DmesgTest finding two suspicious errors: uvesafb: mode switch failed (eax=0x4f02, err=1) fbcon_init: detected unhandled fb_set_par error, error code -22 I couldn't find any related changes since the last successful run (commit 71b0568f). Are these real errors? https://autobuilder.yoctoproject.org/main/builders/nightly-qa-skeleton/builds/476/steps/Running%20Sanity%20Tests/logs/stdio | ====================================================================== | FAIL: test_dmesg (oeqa.runtime.dmesg.DmesgTest) | ---------------------------------------------------------------------- | Traceback (most recent call last): | File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-qa-skeleton/build/meta/lib/oeqa/utils/decorators.py", line 102, in wrapped_f | return func(*args) | File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-qa-skeleton/build/meta/lib/oeqa/utils/decorators.py", line 90, in wrapped_f | return f(*args) | File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-qa-skeleton/build/meta/lib/oeqa/runtime/dmesg.py", line 12, in test_dmesg | self.assertEqual(status, 1, msg = "Error messages in dmesg log: %s" % output) | AssertionError: 0 != 1 : Error messages in dmesg log: fbcon_init: detected unhandled fb_set_par error, error code -22 | | ====================================================================== | FAIL: test_parselogs (oeqa.runtime.parselogs.ParseLogsTest) | ---------------------------------------------------------------------- | Traceback (most recent call last): | File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-qa-skeleton/build/meta/lib/oeqa/utils/decorators.py", line 102, in wrapped_f | return func(*args) | File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-qa-skeleton/build/meta/lib/oeqa/utils/decorators.py", line 90, in wrapped_f | return f(*args) | File "/home/pokybuild/yocto-autobuilder/yocto-worker/nightly-qa-skeleton/build/meta/lib/oeqa/runtime/parselogs.py", line 251, in test_parselogs | self.assertEqual(errcount, 0, msg=self.msg) | AssertionError: 2 != 0 : Log: dmesg | ----------------------- | Central error: fbcon_init: detected unhandled fb_set_par error, error code -22 | *********************** | devtmpfs: mounted | Freeing unused kernel memory: 1332K (ffffffff81f1e000 - ffffffff8206b000) | Write protecting the kernel read-only data: 14336k | Freeing unused kernel memory: 856K (ffff88000192a000 - ffff880001a00000) | Freeing unused kernel memory: 420K (ffff880001d97000 - ffff880001e00000) | random: nonblocking pool is initialized | uvesafb: SeaBIOS Developers, SeaBIOS VBE Adapter, Rev. 1, OEM: SeaBIOS VBE(C) 2011, VBE v3.0 | uvesafb: no monitor limits have been set, default refresh rate will be used | uvesafb: scrolling: redraw | uvesafb: mode switch failed (eax=0x4f02, err=1) | fbcon_init: detected unhandled fb_set_par error, error code -22 | Console: switching to colour frame buffer device 80x30 | uvesafb: framebuffer at 0xfd000000, mapped to 0xffffc90002000000, using 16384k, total 16384k | fb0: VESA VGA frame buffer device | udevd[82]: starting version 182 | EXT4-fs (hda): re-mounted. Opts: data=ordered | | *********************** | Central error: uvesafb: mode switch failed (eax=0x4f02, err=1) | *********************** | VFS: Mounted root (ext4 filesystem) on device 3:0. | devtmpfs: mounted | Freeing unused kernel memory: 1332K (ffffffff81f1e000 - ffffffff8206b000) | Write protecting the kernel read-only data: 14336k | Freeing unused kernel memory: 856K (ffff88000192a000 - ffff880001a00000) | Freeing unused kernel memory: 420K (ffff880001d97000 - ffff880001e00000) | random: nonblocking pool is initialized | uvesafb: SeaBIOS Developers, SeaBIOS VBE Adapter, Rev. 1, OEM: SeaBIOS VBE(C) 2011, VBE v3.0 | uvesafb: no monitor limits have been set, default refresh rate will be used | uvesafb: scrolling: redraw | uvesafb: mode switch failed (eax=0x4f02, err=1) | fbcon_init: detected unhandled fb_set_par error, error code -22 | Console: switching to colour frame buffer device 80x30 | uvesafb: framebuffer at 0xfd000000, mapped to 0xffffc90002000000, using 16384k, total 16384k | fb0: VESA VGA frame buffer device | udevd[82]: starting version 182 | EXT4-fs (hda): re-mounted. Opts: data=ordered | | *********************** | 2 errors found in logs.
Having been working through a different uvesafb issue and since we have not seen this issue again, I think it was a transient qemu related issue. If we get this again, let's reopen this. I have not been able to reproduce this at all, nor have we seen it again on the Autobuilder.
verified as per above comments.
Re-opening, it happened again. https://autobuilder.yoctoproject.org/main/builders/nightly-qa-systemd/builds/551/steps/Running%20Sanity%20Tests/logs/stdio | Central error: [ 25.630928] uvesafb: mode switch failed (eax=0x4f02, err=1) | *********************** | [ 18.759981] EXT4-fs (vda): re-mounted. Opts: (null) | [ 18.853306] systemd[1]: Created slice system-getty.slice. | [ 19.644690] systemd[1]: Mounted POSIX Message Queue File System. | [ 19.721811] systemd[1]: Mounted Debug File System. | [ 19.754400] systemd[1]: Mounted Temporary Directory. | [ 19.965656] systemd[1]: Started Setup Virtual Console. | [ 20.066847] systemd[1]: Started Create list of required static device nodes for the current kernel. | [ 20.165234] uvesafb: no monitor limits have been set, default refresh rate will be used | [ 20.208035] systemd[1]: Started Remount Root and Kernel File Systems. | [ 20.215677] uvesafb: scrolling: redraw | [ 25.630928] uvesafb: mode switch failed (eax=0x4f02, err=1) | [ 25.631149] fbcon_init: detected unhandled fb_set_par error, error code -22 | [ 25.688472] Console: switching to colour frame buffer device 80x30 | [ 25.714573] uvesafb: framebuffer at 0xfd000000, mapped to 0xffffc90002000000, using 16384k, total 16384k | [ 25.720115] fb0: VESA VGA frame buffer device | [ 25.899880] systemd[1]: Started Load Kernel Modules. | [ 26.515469] systemd[1]: Starting Apply Kernel Variables... | [ 26.629031] systemd[1]: Mounting NFSD configuration filesystem... | [ 26.808965] systemd[1]: Starting Rebuild Dynamic Linker Cache... | [ 26.994558] systemd[1]: Starting Create System Users... | [ 27.325425] systemd[1]: Starting Rebuild Hardware Database... | | *********************** | Central error: [ 25.631149] fbcon_init: detected unhandled fb_set_par error, error code -22 | *********************** | [ 18.853306] systemd[1]: Created slice system-getty.slice. | [ 19.644690] systemd[1]: Mounted POSIX Message Queue File System. | [ 19.721811] systemd[1]: Mounted Debug File System. | [ 19.754400] systemd[1]: Mounted Temporary Directory. | [ 19.965656] systemd[1]: Started Setup Virtual Console. | [ 20.066847] systemd[1]: Started Create list of required static device nodes for the current kernel. | [ 20.165234] uvesafb: no monitor limits have been set, default refresh rate will be used | [ 20.208035] systemd[1]: Started Remount Root and Kernel File Systems. | [ 20.215677] uvesafb: scrolling: redraw | [ 25.630928] uvesafb: mode switch failed (eax=0x4f02, err=1) | [ 25.631149] fbcon_init: detected unhandled fb_set_par error, error code -22 | [ 25.688472] Console: switching to colour frame buffer device 80x30 | [ 25.714573] uvesafb: framebuffer at 0xfd000000, mapped to 0xffffc90002000000, using 16384k, total 16384k | [ 25.720115] fb0: VESA VGA frame buffer device | [ 25.899880] systemd[1]: Started Load Kernel Modules. | [ 26.515469] systemd[1]: Starting Apply Kernel Variables... | [ 26.629031] systemd[1]: Mounting NFSD configuration filesystem... | [ 26.808965] systemd[1]: Starting Rebuild Dynamic Linker Cache... | [ 26.994558] systemd[1]: Starting Create System Users... | [ 27.325425] systemd[1]: Starting Rebuild Hardware Database... | [ 27.945129] systemd[1]: Mounted NFSD configuration filesystem.
Accepted by Saul
Next time this occurs please see about preserving the v86d log files from the syste, if it exists.
As best as I can tell from reviewing the kernel and v86d code, we are getting some memory corruption during one of the uvesafb_exec calls, there is a retry and the framebuffer does get correctly initialized. As it turns out the logs will not be available because the v86d code is started before the syslog is enabled.
The below log not showing the error is from a build based on Jethro, sato-sdk image on qemux86-64 which should be machine once showed error in above comment. The build include two patches that should 'NOT' be related to this issue though. I feel this could not be a persistent problem. Will do some stress test to try to reproduce it... [ 8.456014] uvesafb: SeaBIOS Developers, SeaBIOS VBE Adapter, Rev. 1, OEM: SeaBIOS VBE(C) 2011, VBE v3.0 [ 8.614386] uvesafb: no monitor limits have been set, default refresh rate will be used [ 8.618753] uvesafb: scrolling: redraw [ 8.679105] Console: switching to colour frame buffer device 80x30 [ 8.690109] uvesafb: framebuffer at 0xfd000000, mapped to 0xffffc90002000000, using 16384k, total 16384k [ 8.690816] fb0: VESA VGA frame buffer device [ 10.857780] udevd[87]: starting version 182 [ 12.834753] EXT4-fs (vda): re-mounted. Opts: (null) [ 24.442758] random: dd urandom read with 52 bits of entropy available [ 41.370941] Bluetooth: BNEP (Ethernet Emulation) ver 1.3 [ 41.371905] Bluetooth: BNEP filters: protocol multicast [ 41.376649] Bluetooth: BNEP socket layer initialized [ 42.760795] Installing knfsd (copyright (C) 1996 okir@monad.swb.de). [ 43.528017] NFSD: Using /var/lib/nfs/v4recovery as the NFSv4 state recovery directory [ 43.549464] NFSD: starting 90-second grace period (net ffffffff81ed6d00)
I still cannot reproduce this issue in a 10 cycle manual test. () Download jethro code (master branch: 1ee08426d792ce27213dd411a885595d8435ae33) () build core-image-sato for qemu-x86-64 machine () runqemu with graphic and serial options with built images () observe log for this issue with commands like "dmesg|grep failed" and "dmesg|grep uvesafb" () Cannot reproduce it in 10 cycles so I am thinking it is relatively sporadic or I really missed any difference between auto builder setup and my test procedure.
Per the discussion today, we cannot reproduce this issue or get more recent failure reports. Close it now. Please reopen when it appears again.
refer to my previous comment for closing.
This bug is still occurring: https://autobuilder.yoctoproject.org/main/builders/nightly-deb-non-deb/builds/373/steps/Running%20Sanity%20Tests/logs/stdio (http://errors.yoctoproject.org/Errors/Details/59135/) also happened a few days ago: http://errors.yoctoproject.org/Errors/Details/31264/ and back in December: http://errors.yoctoproject.org/Errors/Details/22229/ October: http://errors.yoctoproject.org/Errors/Details/20402/ and June: http://errors.yoctoproject.org/Errors/Details/12084/ it takes a while but a search is: http://errors.yoctoproject.org/Errors/Search/?query=fb_set_par+error Please don't close this until we actually get to the bottom of this issue. The bugzilla is full of various reports of this bug. It is hard to reproduce which does make it hard to fix, I appreciate that but the issue should remain open until solved.
That's okay for me to keep this bug open. But need some inputs from people: () Is it a _real_ issue causing any _functional_ problem with qemu? I just try to understand the behavior better before I can successfully reproduce it on my bench. Could we keep context on AB server when it happens? () What's the policy of a monitoring window before we can close a non-100% reproducible bug on yocto (with a possible fix or not)? () what's the official way to query the errors? is error.yoctoproject.org sufficient? Sorry, I am relatively new in yocto, but really hope you guys please share some info so we can reduce ping-pangs in debugging cycle.
Tried to follow dev manual to enable testimage task with sat image, but test always failed at test_ssh test suite which should not be relevant to this issue. However, it means I still cannot automates the official test procedure on my local bench. I am writing a small auto-boot script as alternative without bothering test suites, assuming this error is not caused by any test suites. (The error message happened very soon so the first test may not start at that stage...)
Created attachment 3098 [details] stdio of failure on nightly-deb-non-deb-builds-373 I'd better to keep a copy of stdio in the recent failure before it gets purged on AB server... I still think this issue has nothing to do with AB test context, the attached log shows TEST_QEMUBOOT_TIMEOUT = "1500" which indicates the error in dmesg at 17.178465 sec was far earlier than whole test started.
Created attachment 3099 [details] qemu-auto-relaunch-32bit script
Created attachment 3100 [details] qemu-auto-relaunch-64bit script Following my thoughts in previous comment, I use attached two scripts to automatically run this loop on 3 host machines, one of them running 32 bit: () launch qemu () check if error happens in dmesg () stop and keep qemu alive if error happens or kill qemu for next iteration. My poky head is 53b5dc0d on master branch. But the issue cannot be seen in totally over 4500 iterations among 3 hosts, unless I made any dumb mistake in scripts. I have pulled original images of the latest failed nightly-deb-non-deb Build #373 and will run the same test against them in next days with hope to reproduce the issue. (doubt it...) In parallel, there are still some possiblities I need to check in stack.
Saul forwarded Animal's patch to limit qemu using 5% cpu usage of host, to simulate some extreme situations in AB server. I finally reproduced this error with the patch and my test script (attached) at 8th iteration. On spot, the qemu is still running with good GUI and I can still launch terminal app although it is very slow due to cpu bandwidth. I think we still need to dig out the root cause, but I just don't think it is a super critical problem at this point...
I think it is very possible that we hit a timeout in uvesafb driver because it cannot receive response from user space (v86d) in 5 sec when qemu could not get enough cpu time. The request to switch mode may still be successful eventually. I will confirm this thoughts with some simulation.
Created attachment 3116 [details] PATCH: uvesafb: print a warning message when task timeout occurs
Created attachment 3117 [details] PATCH: Qemu: limit to 5% cpu once it is launched
Wrapping up based on simulation ========================== So far the error message “uvesafb: mode switch failed (eax=0x4f02, err=1)” can only be reproduced in my simulation with Aníbal’s patch that limits host cpu bandwidth to 5% for qemu once it launched. (I cannot reproduce the issue with same test procedure across 3 machines in over 4500 cycles in a normal condition.) In simulation, the uvesafb driver hits a timeout when it cannot get response from user space helper (v86d) for a submitted task (request) in 5 sec, defined by UVESAFB_TIMEOUT in kernel. Compared results from normal case and simulation, it should be caused by the very limited cpu power qemu can get. In the real situation that build server could be under a very heavy build-test load. Simulated test procedure (patches and test scripts attached) () Apply poky patch “Qemu: limit to 5% cpu once it is launched” () Apply kernel patch “print a warning message when task timeout occurs” () build image sato for machine qemux86 or qemux86-64 () in your build dir, run either 32 or 64 bit qemu-auto-relaunch script. This script will do nothing but launch qemu again and again until the concerned error message occurs. Once the test stops, you will see the qemu is alive and you can get dmesg via ssh (very slow though): uvesafb: 5000 ms task timeout occured uvesafb: mode switch failed (eax=0x4f02, err=1) Actually, all existing logs with timestamps show the error after 5 to 8 sec since the last normal uvesab log in dmesg. Our simulation and analysis shouldn’t be very absurd at this point. Of course, same function could be failed or trigger same timeout with a different cause. But so far this is the only course I have seen. If people agree with what I summarized, I don’t think we should fix this issue in kernel because (1) 5 sec is already generous enough to tell bad or good case, even for qemu’s normal case. (2) Any fixed timeout value won’t fit every host machine’s load. No wishful thinking here. Close it as won’t fix and submit new bugs for other causes is what I suggested.
Based on discussion with RP, we will extend timeout value and also provide an error message to make things more clear. I will do it with a 15 sec timeout value. If it works in my server, we can ask AB maintainer to try it.
RP & others, The suggestions from our talk on IRC are (1) extend timeout value and (2) add an error message when timeout happens. I changed timeout from 5 sec to 15 sec but failure still happens after 27 runs. Maybe this won't help in real situation when qemu cannot get bandwidth in a period longer than that. Saul and I think this is not really meaningful. I have submitted a patch to print out an error message to linux-yocto project. Another solution in next stage could be: I will write a patch to add a new boot parameter uvesafb.timeout in driver. It will accept -1 (no timeout) and any positive value in ms. The existing default value 5 sec will be kept when no timeout value specified in kernel command line. In other contexts, this will cause no change in driver behavior. AB server setup can add bootparam="uvesafb.timeout=-1" when call runqemu in do_testimage stage. With -1 in timeout, driver will retry waiting infinitely. Assuming cpu bandwidth issue is the only root cause behind timeout, this change could eliminate different consequent errors from fbcon callers to uvesafb. If we found anything wrong with qemu even with -1 AND enough cpu bandwidth, that means there could be something deeper and we can start further troubleshooting from this point. AB server can also take advantage of new boot option to increase the yield rate of these sporadic issues. e.g. set timeout to a very small value, say, 100ms. Let me know if this is a better approach. ------------------------------------------ Actually, today I also triggered another variant of this type of errors with same simulation: [ 126.670550] uvesafb: 5000 ms task timeout error [ 126.673310] uvesafb: Getting VBE info block failed (eax=0x4f00, err=1) [ 126.673684] uvesafb: vbe_init() failed with -22 [ 126.679748] uvesafb: probe of uvesafb.0 failed with error -22 (The first error line is from new patch.) And there is one similar qemu failure 1~2 years ago: http://errors.yoctoproject.org/Errors/Details/5059/, but there was no timestamp in the old build for a 100% confirmation.
BTW, in the above proposal, new error message will be printed out in both of infinite-retry (-1) and any other timeout numbers.
Lets add the better logging for now and then next time we see this, confirm this is the problem and decide what to do about the timeout then. Thanks for the work on this!
https://lists.yoctoproject.org/pipermail/linux-yocto/2016-April/005078.html Patch for a better logging has been submitted to linux-yocto mailing list last week.
update estimated days as "no effort" since the patch is acceptable for current stage. We should revise it once what I proposed or any new approach is required and prioritized.
The latest occurrence http://errors.yoctoproject.org/Errors/Details/69369/ shows the same timeout problem.
Currently we are not seeing the timeout on the Autobuilders, if this issue returns, we have a plan of action, which Jianxun has outlined below.
Repoen this bug based on a discussion with RP for a recent occurrence: https://autobuilder.yoctoproject.org/main/builders/nightly-rpm-non-rpm/builds/518/steps/Running%20Sanity%20Tests/logs/stdio We think it is time for workaround proposed in this ticket...
Created attachment 3372 [details] WIP: UNTESTED patch for new timeout option in uvesafb I will put this patch to stress test next Mon. An extra change may be needed because uvesafb is compiled as a module for qemu target. That means we either compile it in kernel and tweak timeout via cmdline, or change module loading config at runtime for timeout. I think the first way only for qemu could be better.
Created attachment 3376 [details] WIP V2: UNTESTED patch for new timeout option in uvesafb
Created attachment 3378 [details] Patch for new timeout option in uvesafb
Created attachment 3379 [details] qemu-auto-relaunch-64bit script (For infinite waiting test) Upload bz8245_64_timout.sh for infinite wait test against patch for timeout parameter option. The expected result is we get timeout warning message when issue happens, but the error message from callers shall not be seen with a negative value passed in uvesafb.task_timeout.
The patch for new timeout option is under simulation test in my local host before a final submission.
Created attachment 3384 [details] submitted: Patch for new timeout option in uvesafb
Created attachment 3385 [details] qemu-auto-relaunch-64bit script (For infinite waiting test) Test script used in pre-submission test.
I have submitted patch for new timeout option to linux-yocto mailing list for all kernel versions today. We don't have full AB server setup to exactly reproduce the issue, so I used a shabby script (uploaded) in a 2-day stress test. (Each iteration is very slow due to 5% cpu bandwidth) What's left for this ticket once patch in kernel is merged: () AB server maintainer tweak timeout value as needed for debugging or deployment purposes by adding this to runqemu: bootparams="uvesafb.task_timeout=_your_timeout_in_ms" Any negative value specified will cause an infinite waiting for task completion. Driver will print a warning message at 5000 ms interval once the issue occurs. This is the _intended_ usage to workaround this bug. Any other non-negative timeout value (ms) tells driver how long it will wait for a task's completion. The wait happens only once in this case. () Update whitelist in OE to: whitelist timeout warning for infinite wait only, since this workaround won't fix bandwidth issue on host anyway: "uvesafb: 5000 ms task timeout, infinitely waiting." Remove any other uvesafb errors from whitelist. If we run into the issue again, it simply means a different root cause or the patch is not done correctly.
Merged into oe-core 8097f2da79b7862733494d2321e3dfdb0880804d.