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

Issue 832984 link

Starred by 1 user

Issue metadata

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



Sign in to add a comment

chromeos-cleanup-logs: fails to rotate logs since 3/21

Project Member Reported by gwendal@chromium.org, Apr 13 2018

Issue description

Reviewing disk qual data, I notice net.log is very large because LOG(INFO) is enabled.

For instance, see https://pantheon.corp.google.com/storage/browser/chromeos-moblab-quanta/results/a0:00:ba:d0:0b:ad/72c91a7e2daa11e8a10e2e03a5ded476/153-moblab/192.168.231.102/

DUT is snappy test image R64-10176.76.0. I also see it on R65 release.


 
We do need LOG(INFO) on shill always. whats the size you are seeing and what is your aim here?

Agreed, we can't debug problems without LOG(INFO).

I guess net.log is about 2MB in hardware_StorageQualTrimStress.tar.. is this what the bug refers to?

Most of the activity comes from chatter about wifi networks within range:

2.0M    net.log
1.2M    net.log-no_rep_ep
496K    net.log-no_rep_ep-no_constructed_destroyed

It's probably exacerbated by frequent scans.

Maybe at some point we should reduce the loglevel of messages that involve wifi SSIDs that are not saved in the profile?  Nearly all of our user reports concern SSIDs that the user has already connected to.
273MB in ~10 days. [see crashinfo.192.168.231.102.tgz]

I notice net.log is not under log rotation, like messages. Does it make sense to include net.log?
  797886 "Rep ep updated..."
  323795 "Constructed WiFi service "
...
  70073  Scan on wlan0 from RequestScan
  70588  ScanDone

Indeed, it is rotated, but not truncated. On my test machine:

ls -l net*.log 
-rw-r--r--. 1 syslog root  4075446 Mar 21 14:05 net.1.log
-rw-r--r--. 1 syslog root  4044052 Mar 20 14:04 net.2.log
-rw-r--r--. 1 syslog root  3922113 Mar 19 14:03 net.3.log
-rw-r--r--. 1 syslog root  3943684 Mar 18 14:01 net.4.log
-rw-r--r--. 1 syslog root  4038903 Mar 17 13:59 net.5.log
-rw-r--r--. 1 syslog root  4138444 Mar 16 13:55 net.6.log
-rw-r--r--. 1 syslog root  4733726 Mar 13 17:03 net.7.log
-rw-r--r--. 1 syslog root 91760122 Apr 13 17:58 net.log

for i in net*.log ; do for j in tail head ; do echo -n "$i: $j: " ;  $j -1 $i | cut -c '-50' ; done ; done
net.1.log: tail: 2018-03-21T14:05:38.713982-07:00 INFO shill[2361]:
net.1.log: head: 2018-03-20T14:05:05.410587-07:00 INFO shill[2361]:
net.2.log: tail: 2018-03-20T14:04:05.410320-07:00 INFO shill[2361]:
net.2.log: head: 2018-03-19T14:04:04.143553-07:00 INFO shill[2425]:
net.3.log: tail: 2018-03-19T14:03:04.142849-07:00 INFO shill[2425]:
net.3.log: head: 2018-03-18T14:02:36.162006-07:00 INFO shill[2425]:
net.4.log: tail: 2018-03-18T14:01:36.159256-07:00 INFO shill[2425]:
net.4.log: head: 2018-03-17T14:00:59.099683-07:00 INFO shill[2425]:
net.5.log: tail: 2018-03-17T13:59:59.107588-07:00 INFO shill[2425]:
net.5.log: head: 2018-03-16T13:56:12.247463-07:00 INFO shill[2439]:
net.6.log: tail: 2018-03-16T13:55:12.245597-07:00 INFO shill[2439]:
net.6.log: head: 2018-03-13T17:04:12.075540-07:00 INFO shill[2624]:
net.7.log: tail: 2018-03-13T17:03:12.080826-07:00 INFO shill[2624]:
net.7.log: head: 2018-03-11T17:03:42.151953-07:00 INFO shill[2496]:
net.log: tail: 2018-04-13T18:01:57.372840-07:00 INFO shill[1372]:
net.log: head: 2018-03-21T14:06:38.710759-07:00 INFO shill[2361]:


Actually, it seems the rotation is not working anymore.
Summary: chromeos-cleanup-logs: fails to rotate logs since 3/21 (was: shill: net.log ballons because of log info )
from #5. I see chromeos-cleanup-logs periodically secluded, 

but does nothing after 03/21.

/var/log/messages.1:2018-03-20T14:04:49.987816-07:00 INFO periodic_scheduler[8130]: cleanup_logs: job completed
/var/log/messages.1:2018-03-21T14:06:20.787714-07:00 INFO periodic_scheduler[2931]: cleanup_logs: running /usr/sbin/chromeos-cleanup-logs
/var/log/messages.2:2018-03-19T14:03:37.928374-07:00 INFO periodic_scheduler[1531]: cleanup_logs: job completed
/var/log/messages.2:2018-03-20T14:04:49.832805-07:00 INFO periodic_scheduler[8007]: cleanup_logs: running /usr/sbin/chromeos-cleanup-logs
/var/log/messages.3:2018-03-18T14:02:07.897128-07:00 INFO periodic_scheduler[6925]: cleanup_logs: job completed
/var/log/messages.3:2018-03-19T14:03:37.799317-07:00 INFO periodic_scheduler[1374]: cleanup_logs: running /usr/sbin/chromeos-cleanup-logs
/var/log/messages.4:2018-03-17T14:00:36.659616-07:00 INFO periodic_scheduler[12073]: cleanup_logs: job completed
/var/log/messages.4:2018-03-18T14:02:07.762134-07:00 INFO periodic_scheduler[6802]: cleanup_logs: running /usr/sbin/chromeos-cleanup-logs
/var/log/messages.5:2018-03-16T13:55:37.074441-07:00 INFO periodic_scheduler[3772]: cleanup_logs: job completed
/var/log/messages.5:2018-03-17T14:00:36.499096-07:00 INFO periodic_scheduler[11950]: cleanup_logs: running /usr/sbin/chromeos-cleanup-logs
/var/log/messages.6:2018-03-13T17:03:59.319758-07:00 INFO periodic_scheduler[12690]: cleanup_logs: job completed
/var/log/messages.6:2018-03-16T13:55:36.907527-07:00 INFO periodic_scheduler[3644]: cleanup_logs: running /usr/sbin/chromeos-cleanup-logs
/var/log/messages.7:2018-03-11T17:02:59.746431-07:00 INFO periodic_scheduler[15584]: cleanup_logs: job completed
/var/log/messages.7:2018-03-13T17:03:59.126826-07:00 INFO periodic_scheduler[12563]: cleanup_logs: running /usr/sbin/chromeos-cleanup-logs

/var/log/messages:2018-03-21T14:06:20.919776-07:00 INFO periodic_scheduler[3055]: cleanup_logs: job completed
/var/log/messages:2018-03-22T14:08:52.088298-07:00 INFO periodic_scheduler[21312]: cleanup_logs: running /usr/sbin/chromeos-cleanup-logs
/var/log/messages:2018-03-22T14:08:52.101680-07:00 INFO periodic_scheduler[21315]: cleanup_logs: job completed
/var/log/messages:2018-03-23T14:10:26.635191-07:00 INFO periodic_scheduler[17372]: cleanup_logs: running /usr/sbin/chromeos-cleanup-logs
/var/log/messages:2018-03-23T14:10:26.643427-07:00 INFO periodic_scheduler[17375]: cleanup_logs: job completed
...
periodic_scheduler[5406]: cleanup_logs: running /usr/sbin/chromeos-cleanup-logs
/var/log/messages:2018-04-11T14:51:39.613231-07:00 INFO periodic_scheduler[5409]: cleanup_logs: job completed
/var/log/messages:2018-04-12T14:54:23.423365-07:00 INFO periodic_scheduler[15031]: cleanup_logs: running /usr/sbin/chromeos-cleanup-logs
/var/log/messages:2018-04-12T14:54:23.426681-07:00 INFO periodic_scheduler[15034]: cleanup_logs: job completed

Components: -OS>Systems>Network Tests
On my machine, /var/lib/cleanup_logs_paused is present, it should have been removed once an autotest test is done.
Status: WontFix (was: Untriaged)
rm /var/lib/cleanup_logs_paused address the issue. I am guess I aborted an autotest job on 3/21 and the same thing happen during disk qual when the DUTs were unstable.

Sign in to add a comment