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

Issue 721115 link

Starred by 1 user

Issue metadata

Status: Archived
Owner:
Closed: Jun 2017
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug



Sign in to add a comment

Enhance Logging for CUPS

Project Member Reported by skau@chromium.org, May 10 2017

Issue description

We need more logging if we're going to diagnose issues in the field.

Survey of options:
go/cros-printer-logs

Conclusion is to enhance the logs that CUPS writes to /var/log/messages
go/moar-cups-logs
 

Comment 1 by skau@chromium.org, May 10 2017

Status: Started (was: Untriaged)
Cc: afakhry@chromium.org
+afakhry@ - Following up from our conversation yesterday, could you check to see if the UUIDs in the attached sample log file are caught by the current script that redacts identifying data? Thanks!!
cups_logs_notice.txt
2.9 KB View Download
Re: weifangsun, Please find below the output the log you sent after it passes through the anonymizer. As you can see, the only thing that was scrubbed is the IP address in the last line "Accepted keyboard-interactive/pam for root from ...".

Please let me know if there are other things that need to be scrubbed as well, and if you could also find out whether it has a standard format to help in the detection, that would be very helpful! Thanks!

2017-05-10T17:23:37.857344-07:00 WARNING minijail0[3378]: libminijail[3378]: allowing syscall: connect
2017-05-10T17:23:37.857374-07:00 WARNING minijail0[3378]: libminijail[3378]: allowing syscall: sendto
2017-05-10T17:23:37.864055-07:00 WARNING cupsd[3379]: libminijail[1]: logging seccomp filter failures
2017-05-10T17:23:37.885739-07:00 INFO cupsd[3379]: REQUEST localhost - - "POST /admin/ HTTP/1.1" 401 242 CUPS-Add-Modify-Printer successful-ok
2017-05-10T17:23:37.888466-07:00 INFO cupsd[3379]: REQUEST localhost - lpadmin "POST /admin/ HTTP/1.1" 200 242 CUPS-Add-Modify-Printer successful-ok
2017-05-10T17:23:37.897201-07:00 INFO cupsd[3379]: REQUEST localhost - lpadmin "POST /admin/ HTTP/1.1" 200 2993 CUPS-Add-Modify-Printer successful-ok
2017-05-10T17:23:40.229741-07:00 INFO cupsd[3379]: REQUEST localhost - - "POST /printers/cb738a9f-6433-4d95-a81e-94e4ae0ed30b HTTP/1.1" 200 291 Create-Job successful-ok
2017-05-10T17:23:40.731782-07:00 INFO cupsd[3379]: REQUEST localhost - - "POST /printers/cb738a9f-6433-4d95-a81e-94e4ae0ed30b HTTP/1.1" 200 20632 Send-Document successful-ok
2017-05-10T17:23:40.735930-07:00 INFO cupsd[3379]: REQUEST localhost - - "POST /printers/cb738a9f-6433-4d95-a81e-94e4ae0ed30b HTTP/1.1" 200 199 Close-Job successful-ok
2017-05-10T17:24:10.638461-07:00 INFO cupsd[3379]: REQUEST localhost - - "POST /admin/ HTTP/1.1" 401 242 CUPS-Add-Modify-Printer successful-ok
2017-05-10T17:24:10.641822-07:00 INFO cupsd[3379]: REQUEST localhost - lpadmin "POST /admin/ HTTP/1.1" 200 242 CUPS-Add-Modify-Printer successful-ok
2017-05-10T17:24:10.652958-07:00 INFO cupsd[3379]: REQUEST localhost - lpadmin "POST /admin/ HTTP/1.1" 200 2993 CUPS-Add-Modify-Printer successful-ok
2017-05-10T17:24:14.611159-07:00 INFO cupsd[3379]: REQUEST localhost - - "POST /admin/ HTTP/1.1" 401 242 CUPS-Add-Modify-Printer successful-ok
2017-05-10T17:24:14.621139-07:00 INFO cupsd[3379]: REQUEST localhost - lpadmin "POST /admin/ HTTP/1.1" 200 242 CUPS-Add-Modify-Printer successful-ok
2017-05-10T17:24:14.653131-07:00 INFO cupsd[3379]: REQUEST localhost - lpadmin "POST /admin/ HTTP/1.1" 200 4161 CUPS-Add-Modify-Printer successful-ok
2017-05-10T17:24:16.914999-07:00 INFO cupsd[3379]: REQUEST localhost - - "POST /printers/d17188da-9cd3-44f4-b148-3e1d748a3b0f HTTP/1.1" 200 286 Create-Job successful-ok
2017-05-10T17:24:17.417747-07:00 INFO cupsd[3379]: REQUEST localhost - - "POST /printers/d17188da-9cd3-44f4-b148-3e1d748a3b0f HTTP/1.1" 200 20627 Send-Document successful-ok
2017-05-10T17:24:17.423872-07:00 INFO cupsd[3379]: REQUEST localhost - - "POST /printers/d17188da-9cd3-44f4-b148-3e1d748a3b0f HTTP/1.1" 200 199 Close-Job successful-ok
2017-05-10T17:24:24.461897-07:00 ERR cupsd[3379]: [Job 4] The printer is not responding.
2017-05-10T17:24:37.816417-07:00 INFO cupsd[3379]: REQUEST localhost - - "POST /jobs/ HTTP/1.1" 200 203 Cancel-Job successful-ok
2017-05-10T17:25:26.373141-07:00 INFO sshd[3484]: Accepted keyboard-interactive/pam for root from <IPv4: 1>17 port 59998 ssh2

Comment 4 by skau@chromium.org, May 16 2017

The formats are UUIDs.  The format is xxxxxxxx-xxxx-Mxxx-Nxxx-xxxxxxxxxxxx where x is a hex-digit, M is the UUID version and N is the variant number.  It's 5 groups of characters with 36 total characters including the 4 hyphens.  The format is 8-4-4-4-12.

Source:
https://en.wikipedia.org/wiki/Universally_unique_identifier
Governing RFC https://tools.ietf.org/html/rfc4122
Project Member

Comment 5 by bugdroid1@chromium.org, May 24 2017

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

commit 8fb8758cdb771ccc13116509f024be979c640889
Author: Sean Kau <skau@chromium.org>
Date: Wed May 24 06:59:28 2017

[net-print/cups] Log desired messages at notice

Add log messages for filter names and exit codes as well as logging
printer operations.  This CL changes the cupsd LogLevel from warn to
notice, logging additional printer status.  Additionally, it relablels
logs for filters at CUPSD_LOG_NOTICE so we can diagnose printing issues
reported through feedback.  In total, we should log about 10 lines per
print job.  Previously, nothing was logged if a job was successful.

BUG= chromium:721115 
TEST=Attempt print with a working configuration and a brokend
configuration then examined /var/log/messages to verify the correct
content was included.

Change-Id: Ie9301c8f8ae655b6e8d961ab102ea198c8f3708d
Reviewed-on: https://chromium-review.googlesource.com/503089
Commit-Ready: Sean Kau <skau@chromium.org>
Tested-by: Sean Kau <skau@chromium.org>
Reviewed-by: Andrew de los Reyes <adlr@chromium.org>

[modify] https://crrev.com/8fb8758cdb771ccc13116509f024be979c640889/net-print/cups/files/cupsd.conf
[add] https://crrev.com/8fb8758cdb771ccc13116509f024be979c640889/net-print/cups/files/cups-2.1.4-raise-log-level-for-desired-features.patch
[rename] https://crrev.com/8fb8758cdb771ccc13116509f024be979c640889/net-print/cups/cups-2.1.4-r17.ebuild
[modify] https://crrev.com/8fb8758cdb771ccc13116509f024be979c640889/net-print/cups/cups-2.1.4.ebuild

Thanks both!!

afakhry@ - Are you able to add scrubbing for the UUIDs based on the format guidance that skau@ has provided? I think it's probably safer to remove them. Let me know if I should log another bug for that work to track!
Yes, I can handle this. I can either use this same bug, or a new bug blocking this one, whatever works for you.

Is there a time frame for this issue?
Thanks! Let's use this bug to track. We are planning to include these logs for M60.
Project Member

Comment 9 by bugdroid1@chromium.org, May 24 2017

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/5a59f95a0fcbaa5976fa7e7247f77f430d9d041a

commit 5a59f95a0fcbaa5976fa7e7247f77f430d9d041a
Author: afakhry <afakhry@chromium.org>
Date: Wed May 24 21:04:26 2017

Anonymize UUIDs

Add a pattern to the anonymizer tool to catch and anonymize Universal
Unique Identidiers (UUIDs).

BUG= 721115 
TEST=components_unittests --gtest_filter=AnonymizerToolTest.AnonymizeCustomPatterns

Review-Url: https://codereview.chromium.org/2905723002
Cr-Commit-Position: refs/heads/master@{#474420}

[modify] https://crrev.com/5a59f95a0fcbaa5976fa7e7247f77f430d9d041a/components/feedback/anonymizer_tool.cc
[modify] https://crrev.com/5a59f95a0fcbaa5976fa7e7247f77f430d9d041a/components/feedback/anonymizer_tool_unittest.cc

Re: weifangsun@, Done.
afakhry@ - Thanks so much for the quick turn around!!

Comment 12 by skau@chromium.org, Jun 8 2017

Status: Fixed (was: Started)

Comment 13 by dchan@chromium.org, Jan 22 2018

Status: Archived (was: Fixed)

Sign in to add a comment