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.

 Issue 813270  has been merged into this issue.

skau@ can you please take a look at this? 

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.

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
"

The same failure again:
https://luci-milo.appspot.com/buildbot/chromeos/veyron_speedy-paladin/8106

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).

 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?

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.

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@

 Issue 818871  has been merged into this issue.

 Issue 819411  has been merged into this issue.

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.

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

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?

Could be these package uprevs?

https://chromium-review.googlesource.com/c/chromiumos/overlays/portage-stable/+/938640
https://chromium-review.googlesource.com/c/chromiumos/overlays/portage-stable/+/938317

+valleau@ can you please take a look?

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?

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.

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

As of R67-10472.0.0 all boards are failing consistently.

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

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

Still seeing some flakiness on the veyrons https://stainless.corp.google.com/search?view=matrix&row=model&col=build&first_date=2018-03-13&last_date=2018-03-15&test=%5Eplatform%5C_AddPrinter%5C.generic%24&exclude_cts=true&exclude_not_run=false&exclude_non_release=true&exclude_au=true&exclude_acts=true&exclude_retried=true&exclude_non_production=true

Investigating

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

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

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

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

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

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

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.

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

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