~/.cache/upstart grows enormous

[Scott Moser]

$ du -hs ~/.cache/upstart/
454M /home/smoser/.cache/upstart/

$ ls -altr ~/.cache/upstart/ | egrep "[0-9]{6,} "
-rw-r----- 1 smoser smoser 14105029 Feb 10 08:53 gnome-session.log
-rw-r----- 1 smoser smoser 3112634 Feb 23 23:09 gnome-settings-daemon.log
-rw-r----- 1 smoser smoser 1179973 Feb 24 08:29 indicator-application.log
-rw-r----- 1 smoser smoser 4129955 Feb 24 09:31 hud.log
-rw-r----- 1 smoser smoser 18668572 Feb 24 10:13 unity-panel-service.log
-rw-r----- 1 smoser smoser 429582393 Feb 24 10:13 dbus.log
-rw-r----- 1 smoser smoser 3708061 Feb 24 10:13 gnome-session-ubuntu.log

$ uptime
 10:15:17 up 14 days, 1:20, 24 users, load average: 1.09, 0.95, 1.33

I suspect my desktop has been logged in and being used for about 14 days, but clearly not longer. Also, it has gone through 'apt-get dist-upgrade' in that time (those are possible excuses for the above).

However, I have 450M of data in a ~/.cache/upstart and 430M in a single file.

I'll attach the log shortly.

ProblemType: Bug
DistroRelease: Ubuntu 14.04
Package: upstart 1.11-0ubuntu5
ProcVersionSignature: Ubuntu 3.13.0-8.27-generic 3.13.2
Uname: Linux 3.13.0-8-generic x86_64
ApportVersion: 2.13.2-0ubuntu5
Architecture: amd64
Date: Mon Feb 24 10:11:04 2014
EcryptfsInUse: Yes
InstallationDate: Installed on 2011-10-19 (859 days ago)
InstallationMedia: Ubuntu 11.10 "Oneiric Ocelot" - Release amd64 (20111012)
ProcEnviron:
 TERM=screen-bce
 PATH=(custom, no user)
 XDG_RUNTIME_DIR=<set>
 LANG=en_US.UTF-8
 SHELL=/bin/bash
SourcePackage: upstart
UpgradeStatus: Upgraded to trusty on 2013-05-20 (280 days ago)
UpstartBugCategory: Session
UpstartRunningSessionCount: 1
UpstartRunningSessionVersion: init (upstart 1.11)
UpstartRunningSystemVersion: init (upstart 1.11)

[James Hunt (jamesodhunt)]

This isn't really a bug with Upstart since it appears the problem is that bamfdaemon is spamming dbus somehow. Upstart is simply logging the output.

That said, there is an outstanding merge proposal to have the session logrotate job run periodically which would have avoided so much disk space being taken (although it would also potentially have caused the bamfdaemon problem from being noticed):

https://code.launchpad.net/~jamesodhunt/ubuntu/trusty/upstart/periodic-logrotate

Once approved (and an FFE raised if necessary), this will resolve the Upstart aspect of this issue.

[Scott Moser (smoser)]

Just for the record its not just bamf. I suspect bamf is maybe 10% or even 20% of this.

$ wc -l dbus.log
3623895 dbus.log
$ grep "^$" dbus.log | wc -l
395763
$ grep "bamf" dbus.log | wc -l
260292
$ grep "indicator" dbus.log | wc -l
47000
$ grep "unity-panel-service" dbus.log | wc -l
32281

[Scott Moser (smoser)]

I'd just like to mention, that this level of logging will be deadly to something with a small disk (small ~ 16G). Its not like 2 weeks of uptime is a silly thing. Phones would likely see months of uptime.

[James Hunt (jamesodhunt)]

Scott - agreed. However, the root cause has nothing to do with Upstart.

Yes, we can make Upstart perform more frequent rotations, but I think we need to understand why your log is growing so fast: yours seems to be growing at ~32MB / day, mine grows at ~100k.

Taking a slighly longer peek, it appears that ~30% of the log relates to google content (talk/chat/hangouts?)

[James Hunt (jamesodhunt)]

Just noticed the tagging on this bug - please can you raise a new upstart bug attaching upstart.state (fro /var/log/ or ~/.cache/upstart/). Thanks!

[Scott Moser (smoser)]

regarding google talk/chat/hangouts.
i use chromium-browser and use hangouts for meetings, launching chromium (and firefox) from the panel.

I completely understand the "not upstarts's fault" argument. But something here needs fixing.

[James Hunt (jamesodhunt)]

It looks like the main culprit is the web browser and/or the Google plugins - every Google connection apears to result in a multi-line burst of json being logged. Are you running the browser/plugins with any debug enabled?

[Scott Moser (smoser)]

some notes:
 * bamfdaemon:3853 errors (Source ID...) show up ever time window focus changes (alt-tab or focus-follows-mouse and enter/exit)
 * while 'tail -f' ing the log, i dont see any browser related things showing up (at least not now). tried going to google calendar, google.com, google drive ... I hvae not enabled debug to my knowledge on hangouts. I did notice that visiting a hangout starts the blob of output like:
 [10685:335] 0x7f1993f85330: Initiated connection to GoogleTalkPlugin

[Scott Moser (smoser)]

Some info here,
  It seems that I had a bad 'status' file in ~/.cache/logrotate/status somehow.
~/.cache/upstart/logrotate.conf said:
error: bad top line in state file /home/smoser/.cache/logrotate/status

$ ls -l /home/smoser/.cache/logrotate/status
-rw-r--r-- 1 smoser smoser 385 May 31 2013 /home/smoser/.cache/logrotate/status

after removing that file, then logrotate functions again.

Not sure what could have caused it, but there was binary data in that file when I looked, and 'file' determined it to be 'data' (ie, it was not gzipped, or xml or anything that made sense to me).

After removal and then:
 start logrotate

$ file /home/smoser/.cache/logrotate/status
/home/smoser/.cache/logrotate/status: ASCII text
$ tail -n 5 /home/smoser/.cache/logrotate/status
"/home/smoser/.cache/upstart/unity.log" 2014-3-5-11:16:52
"/home/smoser/.cache/upstart/gnome-settings-daemon.log" 2014-3-5-11:16:52
"/home/smoser/.cache/upstart/window-stack-bridge.log" 2014-3-5-11:16:52
"/home/smoser/.cache/upstart/update-notifier-release.log" 2014-3-5-11:16:52
"/home/smoser/.cache/upstart/update-notifier-crash-_var_crash__bin_bash.1000.crash.log" 2014-3-5-11:16:52

So it would seem something screwed up that file and I was forever stuck.

[James Hunt (jamesodhunt)]

The logrotate job is simply invoking logrotate program so it could be a bug in logrotate? Nobody else appears to have reported this issue.

Do you have a ~/.cache/upstart/logrotate.log containing any errors? We could simply make the job delete the status file if it exists prior to running logrotate since the number of unique user job log files (*.log) is unlikely to grow huge.

[James Hunt (jamesodhunt)]

Do you still have the status file somewhere so we can see what binary data it contained?

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Brian Murray (brian-murray)]

I have some log files that are also quite large.

-rw-r----- 1 bdmurray bdmurray 54M Apr 11 09:15 hud.log
-rw-r----- 1 bdmurray bdmurray 77M Apr 11 13:06 unity-panel-service.log
-rw-r----- 1 bdmurray bdmurray 964M Apr 11 13:13 dbus.log

[Bryce Nesbitt (bryce2)]

-rw-r----- 1 bnesbitt bnesbitt 6747 Mar 22 08:42 dbus.log
-rw-r----- 1 bnesbitt bnesbitt 20295 Mar 21 07:40 gnome-session-Unity.log.1.gz
-rw-r----- 1 bnesbitt bnesbitt 138016 Mar 20 09:03 gnome-session-Unity.log.3.gz
-rw-r----- 1 bnesbitt bnesbitt 141565 Mar 15 10:43 gnome-session-Unity.log.7.gz
-rw-r----- 1 bnesbitt bnesbitt 173361 Mar 20 22:02 gnome-session-Unity.log.2.gz
-rw-r----- 1 bnesbitt bnesbitt 346368 Mar 19 08:59 gnome-session-Unity.log.4.gz
-rw-r----- 1 bnesbitt bnesbitt 469737 Mar 18 09:36 gnome-session-Unity.log.5.gz
-rw-r----- 1 bnesbitt bnesbitt 529850 Mar 17 10:38 gnome-session-Unity.log.6.gz
-rw-r----- 1 bnesbitt bnesbitt 10686756450 Mar 22 08:44 gnome-session-Unity.log

The gnome log is filled with completely non-actionable log messages for anyone other than the developer of the given app:

(firefox:5419): GLib-GObject-CRITICAL **: g_object_unref: assertion 'object->ref_count > 0' failed
(putty:17960): GLib-CRITICAL **: Source ID 95654 was not found when attempting to remove it

[Bryce Nesbitt (bryce2)]

This is also an issue for SSD owners, as it results in significant write churn on the drive, for no benefit to the owner of the computer.