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

Issue 814340 link

Starred by 5 users

Issue metadata

Status: Fixed
Owner:
Closed: Apr 2018
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 0
Type: Bug



Sign in to add a comment

platform_addPrinter failed on veyron_speedy

Project Member Reported by norvez@chromium.org, Feb 21 2018

Issue description

https://luci-milo.appspot.com/buildbot/chromeos/veyron_speedy-paladin/8069


"
CmdError: Command <cmp /tmp/printing_request.log /usr/local/autotest/tests/platform_AddPrinter/golden_printing_request_generic.bin> failed, rc=2, Command returned non-zero exit status
* Command: 
    cmp /tmp/printing_request.log /usr/local/autotest/tests/platform_AddPrint
    er/golden_printing_request_generic.bin
Exit status: 2
Duration: 0.00946998596191

stderr:
cmp: /tmp/printing_request.log: No such file or directory
"

I noticed this in /var/log/messages:

"
2018-02-21T14:11:17.863064+00:00 NOTICE root[11532]: autotest runtest platform_AddPrinter
2018-02-21T14:11:19.667349+00:00 NOTICE autotest[11551]: 06:11:19.658 WARNI|  external_modules:0057| Unable to import cv2 due to: Incorrect cv2 version found, expected 2.4.8 <= version < 3.0.0, found version $Rev: 4557 $
"

Could that be the explanation?
 

Comment 1 by norvez@chromium.org, Feb 21 2018

Forgot to mention, the CLs that were under test don't seem suspicious but I may have missed something
cupsd failed again:

2018-02-21T14:11:37.182834+00:00 WARNING cupsd[12243]: libminijail[1]: logging seccomp filter failures
2018-02-21T14:11:37.217732+00:00 INFO cupsd[12243]: REQUEST localhost - - "POST /admin/ HTTP/1.1" 401 219 CUPS-Add-Modify-Printer successful-ok
2018-02-21T14:11:37.224654+00:00 INFO cupsd[12243]: REQUEST localhost - lpadmin "POST /admin/ HTTP/1.1" 200 219 CUPS-Add-Modify-Printer successful-ok
2018-02-21T14:11:37.241808+00:00 INFO cupsd[12243]: REQUEST localhost - lpadmin "POST /admin/ HTTP/1.1" 200 3014 CUPS-Add-Modify-Printer successful-ok
2018-02-21T14:11:37.417863+00:00 INFO cupsd[12243]: REQUEST localhost - - "POST /printers/FakePrinterID HTTP/1.1" 200 340 Create-Job successful-ok
2018-02-21T14:11:37.419341+00:00 ERR cupsd[12243]: [Client 7] Unable to create request file "/var/spool/cups/00000001": No such file or directory
2018-02-21T14:11:37.419366+00:00 INFO cupsd[12243]: REQUEST localhost - - "POST /printers/FakePrinterID HTTP/1.1" 413 270 Send-Document -
2018-02-21T14:11:37.419473+00:00 ERR cupsd[12243]: [Client 7] Unable to create request file "/var/spool/cups/00000002": No such file or directory
2018-02-21T14:11:37.419488+00:00 INFO cupsd[12243]: REQUEST localhost - - "POST /printers/FakePrinterID HTTP/1.1" 413 540 Send-Document -
2018-02-21T14:11:37.419593+00:00 ERR cupsd[12243]: [Client 7] Unable to create request file "/var/spool/cups/00000003": No such file or directory
2018-02-21T14:11:37.419609+00:00 INFO cupsd[12243]: REQUEST localhost - - "POST /printers/FakePrinterID HTTP/1.1" 413 810 Send-Document -
2018-02-21T14:11:37.419697+00:00 ERR cupsd[12243]: [Client 7] Unable to create request file "/var/spool/cups/00000004": No such file or directory
2018-02-21T14:11:37.419717+00:00 INFO cupsd[12243]: REQUEST localhost - - "POST /printers/FakePrinterID HTTP/1.1" 413 1080 Send-Document -
2018-02-21T14:11:37.419804+00:00 ERR cupsd[12243]: [Client 7] Unable to create request file "/var/spool/cups/00000005": No such file or directory
2018-02-21T14:11:37.419819+00:00 INFO cupsd[12243]: REQUEST localhost - - "POST /printers/FakePrinterID HTTP/1.1" 413 1350 Send-Document -
2018-02-21T14:11:37.419911+00:00 ERR cupsd[12243]: [Client 7] Unable to create request file "/var/spool/cups/00000006": No such file or directory
2018-02-21T14:11:37.419926+00:00 INFO cupsd[12243]: REQUEST localhost - - "POST /printers/FakePrinterID HTTP/1.1" 413 1620 Send-Document -
2018-02-21T14:11:37.451671+00:00 DEBUG kernel: [ 1459.508977] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2018-02-21T14:11:37.471637+00:00 INFO kernel: [ 1459.527740] binder: 12252:12252 transaction failed 29189, size 0-0
2018-02-21T14:11:38.311633+00:00 INFO kernel: [ 1460.360104] max98090 2-0010: mclk 12288000, pclk 12288000
2018-02-21T14:11:38.968895+00:00 INFO session_manager[11723]: [INFO:child_exit_handler.cc(77)] Handling 12172 exit.
That looks like a different failure to me.

Who owns cups? Can we get that team started on this?

PS: Both of these look like real product bugs to me, not infrastructure.
Cc: xiaochu@chromium.org skau@chromium.org
 Issue 813270  has been merged into this issue.
Owner: skau@chromium.org
skau@ can you please take a look at this? 

Comment 6 by norvez@chromium.org, Feb 21 2018

Since it looks like the test itself is flaky I've annotated the build to exonerate the CLs. Also added an entry in go/croslog.

Comment 7 by skau@chromium.org, Feb 21 2018

Components: Internals>Printing>CUPS

Comment 8 by norvez@chromium.org, Feb 24 2018

It happened again, on the same builder: https://luci-milo.appspot.com/buildbot/chromeos/veyron_speedy-paladin/8090

"
localtime=Feb 23 17:23:30	Command <lp -d FakePrinterID /usr/local/autotest/tests/platform_AddPrinter/to_print.pdf> failed, rc=1, Command returned non-zero exit status
  * Command: 
      lp -d FakePrinterID
      /usr/local/autotest/tests/platform_AddPrinter/to_print.pdf
  Exit status: 1
  Duration: 0.033674955368
  
  stderr:
  lp: Request Entity Too Large
"

Comment 10 by skau@chromium.org, Feb 26 2018

I think it's due to this CL https://chromium-review.googlesource.com/c/chromiumos/platform2/+/472908 since we currently use symlinks there.  I'm going to patch it out (our symlinks).
Cc: nxia@chromium.org wnhuang@chromium.org matthewmwang@chromium.org ejcaruso@chromium.org
 Issue 816637  has been merged into this issue.
CL https://chromium-review.googlesource.com/c/chromiumos/platform2/+/472908 that blocked symlink traversal made the AddPrinter test fail every time. But even though that CL is not in the CQ anymore AddPrinter is still flaky, it sounds like a different issue.
Could this be another symptom of https://bugs.chromium.org/p/chromium/issues/detail?id=783208?
That bug is marked fixed, are you saying that was done in error?
Cc: justincarlson@chromium.org
Sorry for my wrong wording. It is marked fixed which is accurate. 

In cupsd.conf, it creates /var/spool/cups:

check_create /var/spool/cups 0710

I will change .conf file to mark cupsd as a task and observe if this fixes the issue. +Justin in case he has other ideas.
Owner: xiaochu@chromium.org
Owner: skau@chromium.org
chatted with skau@ offline. the folder creation is in pre-start section which should be executed before cupsd is started. And marking it as 'task' does not solve the problem since cupsd is not started during boot. 

assigning back to skau@
Cc: tbarzic@chromium.org x...@chromium.org
 Issue 818871  has been merged into this issue.
 Issue 819411  has been merged into this issue.

Comment 20 by skau@chromium.org, Mar 7 2018

Status: Started (was: Assigned)
I'm investigating a failure in the foomatic-rip filter.  I'll pull the test from the CQ until I can root cause and fix the failure.
Project Member

Comment 21 by bugdroid1@chromium.org, Mar 8 2018

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

commit 453709078da41e537126d6649cf0e78886f6a629
Author: Dylan Reid <dgreid@chromium.org>
Date: Thu Mar 08 22:04:42 2018

platform_AddPrinter: Temporarily remove from CQ

Remove platform_AddPrinter.generic from bvt-cq until we can
track down and fix the root cause of the failure.  This is
occurring too often to be a flake.

BUG= chromium:814340 
TEST=Passes presubmit

Change-Id: I47948e60ed82dea410a00c8fe05df0cf88ee79cf
Reviewed-on: https://chromium-review.googlesource.com/952765
Commit-Ready: Sean Kau <skau@chromium.org>
Tested-by: Sean Kau <skau@chromium.org>
Reviewed-by: Xiaochu Liu <xiaochu@chromium.org>

[modify] https://crrev.com/453709078da41e537126d6649cf0e78886f6a629/client/site_tests/platform_AddPrinter/control.generic

Cc: pgeorgi@chromium.org
The test started failing on all platforms since R67-10472.0.0
https://screenshot.googleplex.com/shjgxgRL2fi

Diff at https://crosland.corp.google.com/log/10471.0.0..10472.0.0 

+pgeorgi@, can you check if +/955639 broke the test on all boards?

Cc: valleau@chromium.org
+valleau@ can you please take a look?

Comment 25 by skau@chromium.org, Mar 10 2018

I don't think the package uprevs broke it.  Looking at the banjo failure from R67-10474.0.0, it's unlikely caused by the gnutls update.

Looks like the printing pipeline is being killed by minijail:
2018-03-09T23:15:49.476609+00:00 WARNING crash_reporter[1685]: Could not load the device policy file.
2018-03-09T23:15:49.476709+00:00 WARNING crash_reporter[1685]: [user] Received crash notification for socket[1684] sig 31, user 277 (developer build - not testing - always dumping)
2018-03-09T23:15:49.478415+00:00 WARNING crash_reporter[1687]: Could not load the device policy file.
2018-03-09T23:15:49.478416+00:00 WARNING crash_reporter[1686]: Could not load the device policy file.
2018-03-09T23:15:49.478516+00:00 WARNING crash_reporter[1686]: [user] Received crash notification for foomatic-rip[1683] sig 31, user 277 (developer build - not testing - always dumping)
2018-03-09T23:15:49.478517+00:00 WARNING crash_reporter[1687]: [user] Received crash notification for pdftopdf[1682] sig 31, user 277 (developer build - not testing - always dumping)


I'll need to look into it.
Could it be that the uprev'ed packages require seccomp policy change to cups?

Comment 27 by skau@chromium.org, Mar 10 2018

It's possible but unlikely since the libraries are crypto related and these shouldn't be doing crypto...  Anyway, I'm going to looking into it.

Comment 28 by pgeorgi@google.com, Mar 10 2018

Just to confirm, 955639 has nothing to do with printers, so won't be the culprit.

Comment 29 by skau@chromium.org, Mar 12 2018

Cc: weifangsun@chromium.org
Labels: -Pri-1 Pri-0
As of R67-10472.0.0 all boards are failing consistently.
Labels: M-67

Comment 31 by skau@chromium.org, Mar 13 2018

Looks like the culprit is getrandom.  Should have a fix tomorrow.
Project Member

Comment 32 by bugdroid1@chromium.org, Mar 14 2018

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/overlays/chromiumos-overlay/+/9ec23a3cad05418088696453cefdc1677c76c00b

commit 9ec23a3cad05418088696453cefdc1677c76c00b
Author: Sean Kau <skau@chromium.org>
Date: Wed Mar 14 02:00:28 2018

net-print/cups: Add getrandom to the syscall filter

gnutls now uses getrandom after the update to 3.5.15. Get random
is used to seed the RNG.

BUG= chromium:814340 
TEST=platform_AddPrinter.generic on cave and veyron_minnie

Change-Id: I1f27708d886b3803116585f0a7d6c6d2dbcf79e1
Reviewed-on: https://chromium-review.googlesource.com/961242
Commit-Ready: Sean Kau <skau@chromium.org>
Tested-by: Sean Kau <skau@chromium.org>
Reviewed-by: Mike Frysinger <vapier@chromium.org>

[rename] https://crrev.com/9ec23a3cad05418088696453cefdc1677c76c00b/net-print/cups/cups-2.1.4-r41.ebuild
[modify] https://crrev.com/9ec23a3cad05418088696453cefdc1677c76c00b/net-print/cups/files/cupsd-seccomp-x86.policy
[modify] https://crrev.com/9ec23a3cad05418088696453cefdc1677c76c00b/net-print/cups/files/cupsd-seccomp-arm.policy
[modify] https://crrev.com/9ec23a3cad05418088696453cefdc1677c76c00b/net-print/cups/files/cupsd-seccomp-amd64.policy

Comment 34 by skau@chromium.org, Mar 15 2018

Something strange is happening.  The logs say "Request entity too large" meaning that the declared content length value is too big

https://github.com/apple/cups/blob/2fa1ba3cc0e02799b739ef0e06efc940a8c5a33e/scheduler/client.c#L1180

Comment 35 by skau@chromium.org, Mar 16 2018

Somehow, we're receiving the pdf instead of the postscript file.

Comment 36 by skau@chromium.org, Mar 20 2018

Determined that we're deleting /var/spool/cups as cupsd is starting because cups-clear-state is running simultaneously.

Comment 37 by skau@chromium.org, Mar 20 2018

Prospective fix in-flight.  Testing on veyron_minnie-release-tryjob, veyron_speedy-release-tryjob, reef-release-tryjob, kip-release-tryjob, and kevin-release-tryjob
Project Member

Comment 38 by bugdroid1@chromium.org, Mar 29 2018

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/overlays/chromiumos-overlay/+/11c60df8b6573af6fa9a3ce2958da43e78f8a918

commit 11c60df8b6573af6fa9a3ce2958da43e78f8a918
Author: Sean Kau <skau@chromium.org>
Date: Thu Mar 29 02:34:22 2018

net-print/cups: Add stop on to cups-clear-state

We need cupsd startup to wait on cups-clear-state to complete or
we risk deleting /var/cache/cups and /var/spool/cups which
breaks the cups daemon.  Per
http://upstart.ubuntu.com/cookbook/#job-lifecycle adding
'stop on starting cupsd' will cause cupsd to wait for up to 5
seconds for cups-clear-state to complete before running pre-start
(which ensures that /var/cache/cups and /var/spool/cups were
created).

BUG= chromium:814340 
TEST=test_that ... platform_AddPrinter.generic on a veryon_minnie

Change-Id: I7989719a57bbe886217ce465bcfff477f642ef67
Reviewed-on: https://chromium-review.googlesource.com/971348
Commit-Ready: Sean Kau <skau@chromium.org>
Tested-by: Sean Kau <skau@chromium.org>
Reviewed-by: Xiaochu Liu <xiaochu@chromium.org>

[rename] https://crrev.com/11c60df8b6573af6fa9a3ce2958da43e78f8a918/net-print/cups/cups-2.1.4-r44.ebuild
[modify] https://crrev.com/11c60df8b6573af6fa9a3ce2958da43e78f8a918/net-print/cups/files/init/cups-clear-state.conf

Project Member

Comment 39 by bugdroid1@chromium.org, Mar 30 2018

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

commit 5e98ad75d5a6ea2ad97043c79d98bf3a7e2ae0e0
Author: Sean Kau <skau@chromium.org>
Date: Fri Mar 30 02:51:52 2018

autotest-tests: Check for timeout in platform_AddPrinter

Record if the server thread timesout.  This could be a
cause of the missing request file.

BUG= chromium:814340 
TEST=Passes on cave. Still fails for veyron_minnie.

Change-Id: I91dd567ac7483d6317f43cdb34afb4af64d341fb
Reviewed-on: https://chromium-review.googlesource.com/965406
Commit-Ready: Sean Kau <skau@chromium.org>
Tested-by: Sean Kau <skau@chromium.org>
Reviewed-by: Xiaochu Liu <xiaochu@chromium.org>

[modify] https://crrev.com/5e98ad75d5a6ea2ad97043c79d98bf3a7e2ae0e0/client/site_tests/platform_AddPrinter/platform_AddPrinter.py

Comment 40 by skau@chromium.org, Apr 9 2018

We don't actually need to login in this test.  Removing login fixes the CUPS reset since we no longer get login-prompt-shown events.
Project Member

Comment 41 by bugdroid1@chromium.org, Apr 11 2018

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

commit 69574d25304a5fd9cd3f25e69001f969269ea686
Author: Sean Kau <skau@chromium.org>
Date: Wed Apr 11 02:13:25 2018

autotest: platform_Add_Printer stop logging in

We no longer need Chrome running to perform the test
so stop opening it.  This fixes the flakiness in
platform_AddPrinter.generic since OOBE no longer runs.
OOBE was causing the CUPS resets.

BUG= chromium:814340 
TEST=Run platform_AddPrinter.generic on veyron_minnie 100
times.  0 flakes.

Change-Id: I613be436b371cae6972e60a540f7120d9aa14c7c
Reviewed-on: https://chromium-review.googlesource.com/1003150
Commit-Ready: ChromeOS CL Exonerator Bot <chromiumos-cl-exonerator@appspot.gserviceaccount.com>
Tested-by: Sean Kau <skau@chromium.org>
Reviewed-by: Xiaochu Liu <xiaochu@chromium.org>

[modify] https://crrev.com/69574d25304a5fd9cd3f25e69001f969269ea686/client/site_tests/platform_AddPrinter/platform_AddPrinter.py

Project Member

Comment 42 by bugdroid1@chromium.org, Apr 18 2018

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

commit 89ab4c2022756183b23071abf42f5ac993476bc3
Author: Sean Kau <skau@chromium.org>
Date: Wed Apr 18 21:02:08 2018

autotest: Restore platform_AddPrinter.generic to bvt-cq

Underlying bug causing printer_AddPlatform.generic to fail
has been resolved.  Restoring test to the CQ.

Release bots are clean since R67-10566.0.0
Current build is R68-10588.0.0

BUG= chromium:814340 
TEST=Passes on trybots kevin, veryon_speedy, cave, and kip

Change-Id: Ib88f6d640398ab19049ac7e84e4c1362d52eaaf8
Reviewed-on: https://chromium-review.googlesource.com/962995
Commit-Ready: Sean Kau <skau@chromium.org>
Tested-by: Sean Kau <skau@chromium.org>
Reviewed-by: Xiaochu Liu <xiaochu@chromium.org>

[modify] https://crrev.com/89ab4c2022756183b23071abf42f5ac993476bc3/client/site_tests/platform_AddPrinter/control.generic

Comment 43 by skau@chromium.org, Apr 18 2018

Status: Fixed (was: Started)

Sign in to add a comment