New issue
Advanced search Search tips
Note: Color blocks (like █ or █) mean that a user may not be available. Tooltip shows the reason.

Issue 740751 link

Starred by 3 users
Status: Verified
Owner:
█ djmk@chromium.org
Last visit > 30 days ago
Closed: Jul 2017
Cc:
glevin@chromium.org
ihf@chromium.org
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 1
Type: Bug



Sign in to add a comment

crtcScreenshot() failed with "ValueError: NULL pointer access" in VM (flaky)

Project Member Reported by derat@chromium.org, Jul 10 2017 
In https://uberchromegw.corp.google.com/i/chromeos/builders/caroline-chrome-pfq/builds/202, cheets_KeyboardTest failed in the first VMTest stage:

INFO	----	----	kernel=3.18.0-15782-gb2d5390210f0	localtime=Jul 10 16:13:59	timestamp=1499721239	
START	----	----	timestamp=1499721240	localtime=Jul 10 16:14:00	
	START	cheets_KeyboardTest	cheets_KeyboardTest	timestamp=1499721240	localtime=Jul 10 16:14:00	
		FAIL	cheets_KeyboardTest	cheets_KeyboardTest	timestamp=1499721347	localtime=Jul 10 16:15:47	Unhandled ValueError: NULL pointer access
	END FAIL	cheets_KeyboardTest	cheets_KeyboardTest	timestamp=1499721347	localtime=Jul 10 16:15:47	
END GOOD	----	----	timestamp=1499721348	localtime=Jul 10 16:15:48	

It apparently passed in the second run.

Here's the test directory: https://pantheon.corp.google.com/storage/browser/chromeos-image-archive/caroline-chrome-pfq/R61-9732.0.0-rc1/vm_test_results_1/pfq_suite/test_harness/all/SimpleTestUpdateAndVerify/2_autotest_tests/results-13-cheets_KeyboardTest

Here's the end of the debug log:

...
07/10 16:15:42.719 DEBUG|    cros_interface:0410| rm -rf /tmp/extension_g9zyq
07/10 16:15:42.818 DEBUG|   logging_manager:0627| Logging subprocess finished
07/10 16:15:42.833 DEBUG|   logging_manager:0627| Logging subprocess finished
07/10 16:15:42.859 DEBUG|             utils:0212| Running 'mkdir -p /usr/local/autotest/results/default/cheets_KeyboardTest/sysinfo/var/spool'
07/10 16:15:42.942 DEBUG|             utils:0212| Running 'rsync --no-perms --chmod=ugo+r -a --exclude=autoserv* --safe-links --exclude=*.core /var/spool/crash /usr/local/autotest/results/default/cheets_KeyboardTest/sysinfo/var/spool'
07/10 16:15:43.212 DEBUG|             utils:0212| Running 'rm -rf /var/spool/crash/*'
07/10 16:15:43.358 DEBUG|             utils:0212| Running 'gzip -9 "/usr/local/autotest/results/default/cheets_KeyboardTest/sysinfo/dmesg"'
07/10 16:15:43.389 DEBUG|             utils:0212| Running 'mkdir -p /usr/local/autotest/results/default/cheets_KeyboardTest/sysinfo/tmp'
07/10 16:15:43.403 DEBUG|             utils:0212| Running 'rsync --no-perms --chmod=ugo+r -a --exclude=autoserv* --safe-links  /tmp/crash_reporter /usr/local/autotest/results/default/cheets_KeyboardTest/sysinfo/tmp'
07/10 16:15:43.417 DEBUG|             utils:0212| Running 'rm -rf /tmp/crash_reporter/*'
07/10 16:15:43.434 DEBUG|             utils:0212| Running 'gzip -9 "/usr/local/autotest/results/default/cheets_KeyboardTest/sysinfo/journal"'
07/10 16:15:43.455 DEBUG|             utils:0212| Running 'grep MemTotal /proc/meminfo'
07/10 16:15:43.474 DEBUG|             utils:0212| Running 'cat /etc/lsb-release'
07/10 16:15:43.559 DEBUG|             utils:0212| Running 'crossystem hwid'
07/10 16:15:43.569 DEBUG|             utils:0212| Running 'crossystem mainfw_type'
07/10 16:15:43.578 INFO |      site_sysinfo:0368| HWID not available; not logging it as a test keyval.
07/10 16:15:43.581 DEBUG|             utils:0212| Running '/opt/google/chrome/chrome --version'
07/10 16:15:43.837 DEBUG|             utils:0212| Running '/usr/sbin/cryptohome --action=tpm_more_status | grep : 2>&1'
07/10 16:15:46.064 DEBUG|             utils:0280| [stdout]   enabled: false
07/10 16:15:46.066 DEBUG|             utils:0280| [stdout]   owned: false
07/10 16:15:46.067 DEBUG|             utils:0280| [stdout]   initialized: false
07/10 16:15:46.068 DEBUG|             utils:0280| [stdout]   attestation_prepared: false
07/10 16:15:46.068 DEBUG|             utils:0280| [stdout]   attestation_enrolled: false
07/10 16:15:46.069 DEBUG|             utils:0280| [stdout]   install_lockbox_finalized: false
07/10 16:15:46.069 DEBUG|             utils:0280| [stdout]   boot_lockbox_finalized: false
07/10 16:15:46.070 DEBUG|             utils:0280| [stdout]   verified_boot_measured: false
07/10 16:15:46.501 DEBUG|             utils:0212| Running 'mkdir -p /usr/local/autotest/results/default/cheets_KeyboardTest/sysinfo/var'
07/10 16:15:46.519 DEBUG|             utils:0212| Running 'rsync --no-perms --chmod=ugo+r -a --exclude=autoserv* --safe-links  /var/log /usr/local/autotest/results/default/cheets_KeyboardTest/sysinfo/var'
07/10 16:15:46.817 ERROR|          parallel:0026| child process failed
07/10 16:15:46.867 DEBUG|          parallel:0030| Traceback (most recent call last):
07/10 16:15:46.868 DEBUG|          parallel:0030|   File "/usr/local/autotest/bin/parallel.py", line 18, in fork_start
07/10 16:15:46.868 DEBUG|          parallel:0030|     l()
07/10 16:15:46.869 DEBUG|          parallel:0030|   File "/usr/local/autotest/bin/job.py", line 483, in <lambda>
07/10 16:15:46.869 DEBUG|          parallel:0030|     l = lambda : test.runtest(self, url, tag, args, dargs)
07/10 16:15:46.869 DEBUG|          parallel:0030|   File "/usr/local/autotest/bin/test.py", line 117, in runtest
07/10 16:15:46.869 DEBUG|          parallel:0030|     job.sysinfo.log_after_each_iteration)
07/10 16:15:46.870 DEBUG|          parallel:0030|   File "/usr/local/autotest/common_lib/test.py", line 902, in runtest
07/10 16:15:46.870 DEBUG|          parallel:0030|     mytest._exec(args, dargs)
07/10 16:15:46.870 DEBUG|          parallel:0030|   File "/usr/local/autotest/common_lib/test.py", line 610, in _exec
07/10 16:15:46.871 DEBUG|          parallel:0030|     _call_test_function(self.execute, *p_args, **p_dargs)
07/10 16:15:46.871 DEBUG|          parallel:0030|   File "/usr/local/autotest/common_lib/test.py", line 824, in _call_test_function
07/10 16:15:46.871 DEBUG|          parallel:0030|     raise error.UnhandledTestFail(e)
07/10 16:15:46.872 DEBUG|          parallel:0030| UnhandledTestFail: Unhandled ValueError: NULL pointer access
07/10 16:15:46.872 DEBUG|          parallel:0030| Traceback (most recent call last):
07/10 16:15:46.872 DEBUG|          parallel:0030|   File "/usr/local/autotest/common_lib/test.py", line 818, in _call_test_function
07/10 16:15:46.873 DEBUG|          parallel:0030|     return func(*args, **dargs)
07/10 16:15:46.873 DEBUG|          parallel:0030|   File "/usr/local/autotest/common_lib/test.py", line 471, in execute
07/10 16:15:46.873 DEBUG|          parallel:0030|     dargs)
07/10 16:15:46.874 DEBUG|          parallel:0030|   File "/usr/local/autotest/common_lib/test.py", line 348, in _call_run_once_with_retry
07/10 16:15:46.874 DEBUG|          parallel:0030|     postprocess_profiled_run, args, dargs)
07/10 16:15:46.874 DEBUG|          parallel:0030|   File "/usr/local/autotest/common_lib/test.py", line 395, in _call_run_once
07/10 16:15:46.875 DEBUG|          parallel:0030|     hook(self)
07/10 16:15:46.875 DEBUG|          parallel:0030|   File "/usr/local/autotest/common_lib/cros/arc.py", line 401, in _after_iteration_hook
07/10 16:15:46.875 DEBUG|          parallel:0030|     image = crtcScreenshot()
07/10 16:15:46.876 DEBUG|          parallel:0030|   File "/usr/local/autotest/cros/graphics/drm.py", line 681, in crtcScreenshot
07/10 16:15:46.876 DEBUG|          parallel:0030|     framebuffer = crtc.fb()
07/10 16:15:46.876 DEBUG|          parallel:0030|   File "/usr/local/autotest/cros/graphics/drm.py", line 212, in fb
07/10 16:15:46.877 DEBUG|          parallel:0030|     fb = self._l.drmModeGetFB(self._fd, self.buffer_id).contents
07/10 16:15:46.877 DEBUG|          parallel:0030| ValueError: NULL pointer access
07/10 16:15:46.877 DEBUG|          parallel:0030| 
07/10 16:15:47.073 INFO |               job:0227| 		FAIL	cheets_KeyboardTest	cheets_KeyboardTest	timestamp=1499721347	localtime=Jul 10 16:15:47	Unhandled ValueError: NULL pointer access
  Traceback (most recent call last):
    File "/usr/local/autotest/common_lib/test.py", line 818, in _call_test_function
      return func(*args, **dargs)
    File "/usr/local/autotest/common_lib/test.py", line 471, in execute
      dargs)
    File "/usr/local/autotest/common_lib/test.py", line 348, in _call_run_once_with_retry
      postprocess_profiled_run, args, dargs)
    File "/usr/local/autotest/common_lib/test.py", line 395, in _call_run_once
      hook(self)
    File "/usr/local/autotest/common_lib/cros/arc.py", line 401, in _after_iteration_hook
      image = crtcScreenshot()
    File "/usr/local/autotest/cros/graphics/drm.py", line 681, in crtcScreenshot
      framebuffer = crtc.fb()
    File "/usr/local/autotest/cros/graphics/drm.py", line 212, in fb
      fb = self._l.drmModeGetFB(self._fd, self.buffer_id).contents
  ValueError: NULL pointer access
07/10 16:15:47.117 INFO |               job:0227| 	END FAIL	cheets_KeyboardTest	cheets_KeyboardTest	timestamp=1499721347	localtime=Jul 10 16:15:47	
07/10 16:15:47.132 DEBUG|          base_job:0357| Persistent state client._record_indent now set to 1
07/10 16:15:47.138 DEBUG|          base_job:0384| Persistent state client.unexpected_reboot deleted
07/10 16:15:48.760 DEBUG|             utils:0212| Running 'rm -f /var/lib/cleanup_logs_paused'
07/10 16:15:48.820 INFO |               job:0227| END GOOD	----	----	timestamp=1499721348	localtime=Jul 10 16:15:48	
07/10 16:15:48.835 DEBUG|          base_job:0357| Persistent state client._record_indent now set to 0
07/10 16:15:48.967 DEBUG|   logging_manager:0627| Logging subprocess finished
07/10 16:15:48.965 DEBUG|   logging_manager:0627| Logging subprocess finished

Comment 1 by ihf@chromium.org, Jul 11 2017

Labels: -OS-Linux M-61 OS-Chrome
Owner: djmk@chromium.org
Summary: crtcScreenshot() failed with "ValueError: NULL pointer access" in VM (flaky) (was: Flaky cheets_KeyboardTest on caroline-chrome-pfq: crtcScreenshot() failed with "ValueError: NULL pointer access")
Project Member

Comment 2 by bugdroid1@chromium.org, Jul 13 2017 

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/autotest/+/ce8ebd68a9dfbc41cead33e9dc594a2b40f0c6d0

commit ce8ebd68a9dfbc41cead33e9dc594a2b40f0c6d0
Author: Ilja H. Friedel <ihf@chromium.org>
Date: Thu Jul 13 16:57:12 2017

arc.py: Handle screenshot failure.

There is no guarantee that the screenshot succeeds. Handle exception to
preserve original failure.

BUG= chromium:740751 
TEST=None.

Change-Id: I39aa3f2ff5e39a5c914fa2c15d03cc2f6852500c
Reviewed-on: https://chromium-review.googlesource.com/567526
Reviewed-by: Joe Kniss <djmk@google.com>
Tested-by: Ilja H. Friedel <ihf@chromium.org>

[modify] https://crrev.com/ce8ebd68a9dfbc41cead33e9dc594a2b40f0c6d0/client/common_lib/cros/arc.py

Comment 3 by ihf@chromium.org, Jul 18 2017

Status: Verified (was: Available)
Original failure preserved now:

07/16 04:15:21.763 DEBUG|             utils:0212| Running 'logger "autotest finished iteration /usr/local/autotest/results/default/cheets_KeyboardTest/sysinfo/iteration.1"'
07/16 04:15:21.775 WARNI|               arc:0402| Iteration 1 failed, taking a screenshot.
07/16 04:15:21.857 WARNI|               arc:0411| Unable to capture screenshot. <type 'exceptions.ValueError'>
07/16 04:15:21.866 DEBUG|              test:0396| after_iteration_hooks completed
07/16 04:15:21.866 WARNI|              test:0616| The test failed with the following exception
Traceback (most recent call last):
  File "/usr/local/autotest/common_lib/test.py", line 610, in _exec
    _call_test_function(self.execute, *p_args, **p_dargs)
  File "/usr/local/autotest/common_lib/test.py", line 818, in _call_test_function
    return func(*args, **dargs)
  File "/usr/local/autotest/common_lib/test.py", line 471, in execute
    dargs)
  File "/usr/local/autotest/common_lib/test.py", line 348, in _call_run_once_with_retry
    postprocess_profiled_run, args, dargs)
  File "/usr/local/autotest/common_lib/test.py", line 381, in _call_run_once
    self.run_once(*args, **dargs)
  File "/usr/local/autotest/tests/cheets_KeyboardTest/cheets_KeyboardTest.py", line 49, in run_once
    sleep_interval=1)  # second
  File "/usr/local/autotest/common_lib/utils.py", line 2747, in poll_for_condition
    raise TimeoutError(desc)
TimeoutError: Timed out waiting for condition: Expected text entered
►

Sign in to add a comment