Failure to cleanup temporary files after filesystem full errors

[bernie]

Using Browse, a user downloaded the GCompris bundle to the Journal, while the filesystem was almost full.

After a while, the user got the warning dialog asking to free some space in the journal. However, the dialog was unresponsive. After some time, the system came back to life, but there was even less free space.

Looking at the process table, we found that sugar-session had spown a long-running zip process to unpack the bundle.

We found that the directory ~/.sugar/default/data contained a few temporary files left behind by the bundle installation process:

total 381258
drwxr-xr-x  2 olpc olpc         0 Mar 29 20:27 .
drwxr-x--- 17 olpc olpc         0 Mar 29 19:42 ..
-rw----r--  2 olpc olpc  85923864 Mar 29 20:14 242d0a4f-cf5c-40eb-9143-ed8c4fd4a8ef.xo
-rw----r--  4 olpc olpc  50069958 Mar 29 18:53 67a30a08-bbd2-4bb2-8aa6-362472f3e7c5_1.xo
-rw----r--  2 olpc olpc 102171151 Mar 29 19:20 d14d6c40-31b0-4962-bd74-d51e9dd33a60.xo
-rw----r--  2 olpc olpc 102171151 Mar 29 19:20 d14d6c40-31b0-4962-bd74-d51e9dd33a60_1.xo
-rw----r--  4 olpc olpc  50069958 Mar 29 18:53 f68b31c0-2c26-454a-a70b-bd474cefc320.xo

The shell.log contained plenty of errors:

1269894065.424218 WARNING root: Could not read bundle:
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/jarabe/journal/misc.py", line 70, in get_icon_name
    bundle = ActivityBundle(file_path)
  File "/usr/lib/python2.6/site-packages/sugar/bundle/activitybundle.py", line 48, in __init__
    Bundle.__init__(self, path)
  File "/usr/lib/python2.6/site-packages/sugar/bundle/bundle.py", line 68, in __init__
    self._zip_file = zipfile.ZipFile(self._path)
  File "/usr/lib/python2.6/zipfile.py", line 698, in __init__
    self._GetContents()
  File "/usr/lib/python2.6/zipfile.py", line 718, in _GetContents
    self._RealGetContents()
  File "/usr/lib/python2.6/zipfile.py", line 730, in _RealGetContents
    raise BadZipfile, "File is not a zip file"
BadZipfile: File is not a zip file

Exception AttributeError: "'ActivityBundle' object has no attribute '_zip_file'" in <bound method ActivityBundle.__del__ of <sugar.bundle.activitybundle.ActivityBundle object at 0xa08b58c>> ignored
1269894065.456154 WARNING root: Could not read bundle:
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/jarabe/journal/misc.py", line 70, in get_icon_name
    bundle = ActivityBundle(file_path)
  File "/usr/lib/python2.6/site-packages/sugar/bundle/activitybundle.py", line 48, in __init__
    Bundle.__init__(self, path)
  File "/usr/lib/python2.6/site-packages/sugar/bundle/bundle.py", line 68, in __init__
    self._zip_file = zipfile.ZipFile(self._path)
  File "/usr/lib/python2.6/zipfile.py", line 698, in __init__
    self._GetContents()
  File "/usr/lib/python2.6/zipfile.py", line 718, in _GetContents
    self._RealGetContents()
  File "/usr/lib/python2.6/zipfile.py", line 730, in _RealGetContents
    raise BadZipfile, "File is not a zip file"
BadZipfile: File is not a zip file

Exception AttributeError: "'ActivityBundle' object has no attribute '_zip_file'" in <bound method ActivityBundle.__del__ of <sugar.bundle.activitybundle.ActivityBundle object at 0xa0f49ec>> ignored
1269894190.732246 WARNING root: Could not read bundle:
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/jarabe/journal/misc.py", line 70, in get_icon_name
    bundle = ActivityBundle(file_path)
  File "/usr/lib/python2.6/site-packages/sugar/bundle/activitybundle.py", line 48, in __init__
    Bundle.__init__(self, path)
  File "/usr/lib/python2.6/site-packages/sugar/bundle/bundle.py", line 68, in __init__
    self._zip_file = zipfile.ZipFile(self._path)
  File "/usr/lib/python2.6/zipfile.py", line 698, in __init__
    self._GetContents()
  File "/usr/lib/python2.6/zipfile.py", line 718, in _GetContents
    self._RealGetContents()
  File "/usr/lib/python2.6/zipfile.py", line 730, in _RealGetContents
    raise BadZipfile, "File is not a zip file"
BadZipfile: File is not a zip file

Exception AttributeError: "'ActivityBundle' object has no attribute '_zip_file'" in <bound method ActivityBundle.__del__ of <sugar.bundle.activitybundle.ActivityBundle object at 0x9f4838c>> ignored
1269894190.764178 WARNING root: Could not read bundle:
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/jarabe/journal/misc.py", line 70, in get_icon_name
    bundle = ActivityBundle(file_path)
  File "/usr/lib/python2.6/site-packages/sugar/bundle/activitybundle.py", line 48, in __init__
    Bundle.__init__(self, path)
  File "/usr/lib/python2.6/site-packages/sugar/bundle/bundle.py", line 68, in __init__
    self._zip_file = zipfile.ZipFile(self._path)
  File "/usr/lib/python2.6/zipfile.py", line 698, in __init__
    self._GetContents()
  File "/usr/lib/python2.6/zipfile.py", line 718, in _GetContents
    self._RealGetContents()
  File "/usr/lib/python2.6/zipfile.py", line 730, in _RealGetContents
    raise BadZipfile, "File is not a zip file"
BadZipfile: File is not a zip file

Exception AttributeError: "'ActivityBundle' object has no attribute '_zip_file'" in <bound method ActivityBundle.__del__ of <sugar.bundle.activitybundle.ActivityBundle object at 0x9f4838c>> ignored
1269894208.020501 WARNING root: Could not read bundle:
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/jarabe/journal/misc.py", line 70, in get_icon_name
    bundle = ActivityBundle(file_path)
  File "/usr/lib/python2.6/site-packages/sugar/bundle/activitybundle.py", line 48, in __init__
    Bundle.__init__(self, path)
  File "/usr/lib/python2.6/site-packages/sugar/bundle/bundle.py", line 68, in __init__
    self._zip_file = zipfile.ZipFile(self._path)
  File "/usr/lib/python2.6/zipfile.py", line 698, in __init__
    self._GetContents()
  File "/usr/lib/python2.6/zipfile.py", line 718, in _GetContents
    self._RealGetContents()
  File "/usr/lib/python2.6/zipfile.py", line 730, in _RealGetContents
    raise BadZipfile, "File is not a zip file"
BadZipfile: File is not a zip file

Exception AttributeError: "'ActivityBundle' object has no attribute '_zip_file'" in <bound method ActivityBundle.__del__ of <sugar.bundle.activitybundle.ActivityBundle object at 0xa0f4b0c>> ignored
1269894208.052876 WARNING root: Could not read bundle:
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/jarabe/journal/misc.py", line 70, in get_icon_name
    bundle = ActivityBundle(file_path)
  File "/usr/lib/python2.6/site-packages/sugar/bundle/activitybundle.py", line 48, in __init__
    Bundle.__init__(self, path)
  File "/usr/lib/python2.6/site-packages/sugar/bundle/bundle.py", line 68, in __init__
    self._zip_file = zipfile.ZipFile(self._path)
  File "/usr/lib/python2.6/zipfile.py", line 698, in __init__
    self._GetContents()
  File "/usr/lib/python2.6/zipfile.py", line 718, in _GetContents
    self._RealGetContents()
  File "/usr/lib/python2.6/zipfile.py", line 730, in _RealGetContents
    raise BadZipfile, "File is not a zip file"
BadZipfile: File is not a zip file

Exception AttributeError: "'ActivityBundle' object has no attribute '_zip_file'" in <bound method ActivityBundle.__del__ of <sugar.bundle.activitybundle.ActivityBundle object at 0xa0e912c>> ignored
1269894233.563614 WARNING root: Could not read bundle:
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/jarabe/journal/misc.py", line 70, in get_icon_name
    bundle = ActivityBundle(file_path)
  File "/usr/lib/python2.6/site-packages/sugar/bundle/activitybundle.py", line 48, in __init__
    Bundle.__init__(self, path)
  File "/usr/lib/python2.6/site-packages/sugar/bundle/bundle.py", line 68, in __init__
    self._zip_file = zipfile.ZipFile(self._path)
  File "/usr/lib/python2.6/zipfile.py", line 698, in __init__
    self._GetContents()
  File "/usr/lib/python2.6/zipfile.py", line 718, in _GetContents
    self._RealGetContents()
  File "/usr/lib/python2.6/zipfile.py", line 730, in _RealGetContents
    raise BadZipfile, "File is not a zip file"
BadZipfile: File is not a zip file

Exception AttributeError: "'ActivityBundle' object has no attribute '_zip_file'" in <bound method ActivityBundle.__del__ of <sugar.bundle.activitybundle.ActivityBundle object at 0xa0a9acc>> ignored
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/jarabe/journal/palettes.py", line 139, in __erase_activate_cb
    bundle = misc.get_bundle(self._metadata)
  File "/usr/lib/python2.6/site-packages/jarabe/journal/misc.py", line 102, in get_bundle
    return ActivityBundle(file_path)
  File "/usr/lib/python2.6/site-packages/sugar/bundle/activitybundle.py", line 48, in __init__
    Bundle.__init__(self, path)
  File "/usr/lib/python2.6/site-packages/sugar/bundle/bundle.py", line 68, in __init__
    self._zip_file = zipfile.ZipFile(self._path)
  File "/usr/lib/python2.6/zipfile.py", line 698, in __init__
    self._GetContents()
  File "/usr/lib/python2.6/zipfile.py", line 718, in _GetContents
    self._RealGetContents()
  File "/usr/lib/python2.6/zipfile.py", line 730, in _RealGetContents
    raise BadZipfile, "File is not a zip file"
zipfile.BadZipfile: File is not a zip file
1269894238.493667 WARNING root: Could not read bundle:
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/jarabe/journal/misc.py", line 70, in get_icon_name
    bundle = ActivityBundle(file_path)
  File "/usr/lib/python2.6/site-packages/sugar/bundle/activitybundle.py", line 48, in __init__
    Bundle.__init__(self, path)
  File "/usr/lib/python2.6/site-packages/sugar/bundle/bundle.py", line 68, in __init__
    self._zip_file = zipfile.ZipFile(self._path)
  File "/usr/lib/python2.6/zipfile.py", line 698, in __init__
    self._GetContents()
  File "/usr/lib/python2.6/zipfile.py", line 718, in _GetContents
    self._RealGetContents()
  File "/usr/lib/python2.6/zipfile.py", line 730, in _RealGetContents
    raise BadZipfile, "File is not a zip file"
BadZipfile: File is not a zip file

Exception AttributeError: "'ActivityBundle' object has no attribute '_zip_file'" in <bound method ActivityBundle.__del__ of <sugar.bundle.activitybundle.ActivityBundle object at 0xa0fa4ec>> ignored
Exception AttributeError: "'ActivityBundle' object has no attribute '_zip_file'" in <bound method ActivityBundle.__del__ of <sugar.bundle.activitybundle.ActivityBundle object at 0xa08bd2c>> ignored
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/jarabe/journal/palettes.py", line 139, in __erase_activate_cb
    bundle = misc.get_bundle(self._metadata)
  File "/usr/lib/python2.6/site-packages/jarabe/journal/misc.py", line 102, in get_bundle
    return ActivityBundle(file_path)
  File "/usr/lib/python2.6/site-packages/sugar/bundle/activitybundle.py", line 48, in __init__
    Bundle.__init__(self, path)
  File "/usr/lib/python2.6/site-packages/sugar/bundle/bundle.py", line 68, in __init__
    self._zip_file = zipfile.ZipFile(self._path)
  File "/usr/lib/python2.6/zipfile.py", line 698, in __init__
    self._GetContents()
  File "/usr/lib/python2.6/zipfile.py", line 718, in _GetContents
    self._RealGetContents()
  File "/usr/lib/python2.6/zipfile.py", line 730, in _RealGetContents
    raise BadZipfile, "File is not a zip file"
zipfile.BadZipfile: File is not a zip file
Exception AttributeError: "'ActivityBundle' object has no attribute '_zip_file'" in <bound method ActivityBundle.__del__ of <sugar.bundle.activitybundle.ActivityBundle object at 0xa0a9dac>> ignored
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/jarabe/journal/palettes.py", line 139, in __erase_activate_cb
    bundle = misc.get_bundle(self._metadata)
  File "/usr/lib/python2.6/site-packages/jarabe/journal/misc.py", line 102, in get_bundle
    return ActivityBundle(file_path)
  File "/usr/lib/python2.6/site-packages/sugar/bundle/activitybundle.py", line 48, in __init__
    Bundle.__init__(self, path)
  File "/usr/lib/python2.6/site-packages/sugar/bundle/bundle.py", line 68, in __init__
    self._zip_file = zipfile.ZipFile(self._path)
  File "/usr/lib/python2.6/zipfile.py", line 698, in __init__
    self._GetContents()
  File "/usr/lib/python2.6/zipfile.py", line 718, in _GetContents
    self._RealGetContents()
  File "/usr/lib/python2.6/zipfile.py", line 730, in _RealGetContents
    raise BadZipfile, "File is not a zip file"
zipfile.BadZipfile: File is not a zip file
1269894351.048443 WARNING root: Could not read bundle:
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/jarabe/journal/misc.py", line 70, in get_icon_name
    bundle = ActivityBundle(file_path)
  File "/usr/lib/python2.6/site-packages/sugar/bundle/activitybundle.py", line 48, in __init__
    Bundle.__init__(self, path)
  File "/usr/lib/python2.6/site-packages/sugar/bundle/bundle.py", line 68, in __init__
    self._zip_file = zipfile.ZipFile(self._path)
  File "/usr/lib/python2.6/zipfile.py", line 698, in __init__
    self._GetContents()
  File "/usr/lib/python2.6/zipfile.py", line 718, in _GetContents
    self._RealGetContents()
  File "/usr/lib/python2.6/zipfile.py", line 730, in _RealGetContents
    raise BadZipfile, "File is not a zip file"
BadZipfile: File is not a zip file

Exception AttributeError: "'ActivityBundle' object has no attribute '_zip_file'" in <bound method ActivityBundle.__del__ of <sugar.bundle.activitybundle.ActivityBundle object at 0xa0f114c>> ignored
1269894351.119622 WARNING root: Could not read bundle:
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/jarabe/journal/misc.py", line 70, in get_icon_name
    bundle = ActivityBundle(file_path)
  File "/usr/lib/python2.6/site-packages/sugar/bundle/activitybundle.py", line 48, in __init__
    Bundle.__init__(self, path)
  File "/usr/lib/python2.6/site-packages/sugar/bundle/bundle.py", line 68, in __init__
    self._zip_file = zipfile.ZipFile(self._path)
  File "/usr/lib/python2.6/zipfile.py", line 698, in __init__
    self._GetContents()
  File "/usr/lib/python2.6/zipfile.py", line 718, in _GetContents
    self._RealGetContents()
  File "/usr/lib/python2.6/zipfile.py", line 730, in _RealGetContents
    raise BadZipfile, "File is not a zip file"
BadZipfile: File is not a zip file

Exception AttributeError: "'ActivityBundle' object has no attribute '_zip_file'" in <bound method ActivityBundle.__del__ of <sugar.bundle.activitybundle.ActivityBundle object at 0xa0f120c>> ignored

[mtd]

Do you have the Browse log, by any chance?

I'm not sure whether Browse or the journal should clean up those datastore items; I'm looking at  http://cgit.sugarlabs.org/browse/mainline/tree/downloadmanager.py#n162 - we should probably try to clean up the datastore there.

This patch should properly handle those errors you logged:

diff --git a/src/sugar/bundle/bundle.py b/src/sugar/bundle/bundle.py
index c9763a0..a04c873 100644
--- a/src/sugar/bundle/bundle.py
+++ b/src/sugar/bundle/bundle.py
@@ -72,7 +72,12 @@ class Bundle(object):
         if os.path.isdir(self._path):
             self._zip_file = None
         else:
-            self._zip_file = zipfile.ZipFile(self._path)
+            try:
+                self._zip_file = zipfile.ZipFile(self._path)
+            except (zipfile.error, LargeZipFile), ziperror:
+                raise MalformedBundleException(
+                    "Error accessing zip file %s: %s"
+                    % (self._path, ziperror))
             self._check_zip_bundle()

         # manifest = self._get_file(self._infodir + '/contents')

[bernie]

Sayamindu, could you consider this fix for 0.84?

I have not yet tested it due to lack of time, but it can't be worse than the current behavior, which makes systems unusable.

[bernie]

Btw, why do we write temporary files to a non-temporary directory?
Shouldn't we use /var/tmp instead?

Additionally, shouldn't we clean all temportary files at boot time?

[sascha_silbe]

Replying to bernie:

Btw, why do we write temporary files to a non-temporary directory?

These are not temporary files, but data store check-outs. They need to be on the same file system as the data store so we can use hard links.

Additionally, shouldn't we clean all temportary files at boot time?

We definitely should, though it isn't as critical as it might seem. Because they're hard links, they don't even occupy an inode.

While your patch is a good idea IMO, it doesn't help with your original issue.
The long-running zip (or more likely unzip) process you mentioned lives in sugar.bundle.bundle.Bundle._unzip(). It might be a good idea to
a) check uncompressed size (from ZIP directory) against statvfs().f_bfree (with some additional safety margin) before uncompressing and
b) nice + ionice the unzip process to improve system responsiveness as the unpack happens in the background, without telling the user about it

We should also check what happens if the unpacks dies mid-way without clean-up, e.g. due to power loss. A quick glance at the code suggests it will try to run the incomplete copy, never unpacking it cleanly (without manual intervention).

[bernie]

We should also check what happens if the unpacks dies mid-way
without clean-up, e.g. due to power loss. A quick glance at
the code suggests it will try to run the incomplete copy,
never unpacking it cleanly (without manual intervention).

I'm attaching a trivial patch to take care of the crash case.

While this doesn't completely fix the bug, it lowers its severity down to a non-blocker because now users can recover their systems by simply rebooting them.

[bernie]

Patch by Martin Dangler

[bernie]

Please review this bugfix, it's a critical problem that makes the system unusable for users.

[dsd]

Some of the other problems with unzipping (system unresponsive, no progress meter) can be solved by using Python's internal zip file classes to do the extraction, rather than calling unzip.

The reason it isn't done this way at the moment (according to comments in the source) is that Pythons zip file classes don't provide parsing of the file attributes in order to apply the correct permissions to the extracted files, etc. However, the classes do provide raw access to the attribute values. So it would be possible (and not too hard) to add a bit of code that parses the attributes and applies them as appropriate.

Once you've got that far, #1499 becomes possible, which is of large value in the field.

(not objecting to the patches here, just followed a discussion on the mailing list which points to this ticket as a discussion point for solving problems of lack of responsiveness and progress info)

[tomeu]

Looks like the patches here have bitrotten following discussion in the mailing list?

This ticket has two patches. Both are waiting review?

[bernie]

Partial fix

[bernie]

Replying to tomeu:

Looks like the patches here have bitrotten following discussion in the mailing list?

This ticket has two patches. Both are waiting review?

Both are to be applied. I updated 0001-Cleanup-temporary-files-on-startup.patch to incorporate comments obtained during review.

[tonyforster]

See also related bug #1987

[tomeu]

Replying to bernie:

Replying to tomeu:

Looks like the patches here have bitrotten following discussion in the mailing list?

This ticket has two patches. Both are waiting review?

Both are to be applied. I updated 0001-Cleanup-temporary-files-on-startup.patch to incorporate comments obtained during review.

I was thinking of the comments from Aleksey and me in this thread:

 http://lists.sugarlabs.org/archive/sugar-devel/2010-May/023720.html

[bernie]

Replying to tomeu:

I was thinking of the comments from Aleksey and me in this thread:

 http://lists.sugarlabs.org/archive/sugar-devel/2010-May/023720.html

Yes, there's a new revision of 0001-Cleanup-temporary-files-on-startup.patch attached to this ticket which should address both Aleksey's and your comments:

rm -rf $HOME/.sugar/${SUGAR_PROFILE:-default}/data/*

This supports multiple profiles and is done before cleaning up the logs.

[alsroot]

last patch is based on ml thread
 http://lists.sugarlabs.org/archive/sugar-devel/2010-May/023724.html

[tomeu]

        data_dir = os.path.join(env.get_profile_path(), 'data')

The wiki says that the data dir is for persistent storage and this patch breaks that assumption. Which of the two needs to be fixed?

 http://wiki.sugarlabs.org/go/Development_Team/Low-level_Activity_API#File_Access

[sascha_silbe]

Replying to tomeu:

{{{
data_dir = os.path.join(env.get_profile_path(), 'data')
}}}
The wiki says that the data dir is for persistent storage and this patch breaks that assumption. Which of the two needs to be fixed?

I fell into the same trap. :)
Above is ~/.sugar/<profile>/data (contains hard or symbolic links to data store entries), not ~/.sugar/<profile>/<activity>/data (persistent activity-global data storage).

[tomeu]

Got it, thanks for the patch and to Sascha for telling. Pushed it as  http://git.sugarlabs.org/projects/sugar/repos/mainline/commits/7e5b8ee227

[mtd]

Might be worth committing my patch still to give slightly better errors/error-handling when the problem originally presents itself.

[tomeu]

Replying to mtd:

Might be worth committing my patch still to give slightly better errors/error-handling when the problem originally presents itself.

Sorry, in the future would be good if tickets were split before more than one patch was attached, so their lifecycle didn't got too complicated.

[bernie]

The patch which has been committed as 7e5b8ee227 had an outstanding issue:

 http://lists.sugarlabs.org/archive/sugar-devel/2010-May/023744.html

I suggest replacing it with this other patch which causes the temporary files to be deleted before Sugar has a chance to start:

 http://bugs.sugarlabs.org/attachment/ticket/1876/0001-Cleanup-temporary-files-on-startup.patch

[bernie]

Replying to mtd:

Might be worth committing my patch still to give slightly better errors/error-handling when the problem originally presents itself.

Indeed, your patch is also needed. I have already included it in my builds for the XO-1:

 http://people.sugarlabs.org/bernie/sugar/sugar-0.88-patches/sugar-toolkit/sugar-fix-sl1876.patch

[bernie]

Replying to bernie:

The patch which has been committed as 7e5b8ee227 had an outstanding issue:

 http://lists.sugarlabs.org/archive/sugar-devel/2010-May/023744.html

Never mind, I hadn't noticed that the code was moved in front of cleanup_logs() in the version that was committed.

[bernie]

We still need to apply the patch found in 2.

[tomeu]

Replying to bernie:

We still need to apply the patch found in 2.

Changing the component accordingly.

[erikos]

mtd, thanks for the patch. LargeZipFile must be of zipfile. And the patch has to be re-based the underlying code has slightly changed.

[mtd]

erikos, sorry for not spotting that. fixed and rebased; I've attached
the updated patch against mainline / master.

[erikos]

Thanks Martin for the new patch. I tried to let it log, but was not successful (I did see the error before applying the code though). Like described in the ticket, I do fill up the nand up to slightly more than 50 MB and then do a download. But that only brings up the alert to make space in the Journal.

Which test case did you use?

[bernie]

Ping? This ticket has been stuck for 2 months. I guess it's Martin's turn.

[mtd]

Replying to erikos:

Thanks Martin for the new patch. I tried to let it log, but was not successful (I did see the error before applying the code though).

I don't think my patch improves the end-user experience. It just makes the error message more accurate.

Which test case did you use?

I didn't test it as I don't think my patch is a significant change to the user experience - I just did a drive-by on this bug originally and noticed the exception was not being handled correctly.

I don't think the bug has to wait for me to test - if you want it can just be closed and when I get some time to test properly I'll open a separate bug.