Bug 178347 – FileSystem::deleteFile should log error status

• Status: RESOLVED
• Resolution: FIXED
• Component: WebCore Misc.

[Brent Fulgham]

It would be useful to know why the 'deleteFile' failed so that we could distinguish between multiple processes competing for a file lock, or bad permissions settings on the directories used by WebKit, etc.

[Radar WebKit Bug Importer]

<rdar://problem/35008951>

[Kate Cheney]

Created attachment 376209 [details]
Patch

[Alexey Proskuryakov]

Comment on attachment 376209 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=376209&action=review

> Source/WebCore/Modules/webdatabase/DatabaseTracker.cpp:865
> +                LOG_ERROR("Error deleting database file %s", file.utf8().data());

What are the privacy implications of logging file names?

[Daniel Bates]

Comment on attachment 376209 [details]
Patch

Just passing by, can talk in person if you want advice.... I think this is your first bug, so good job on with picking up the process 🙂. Here are somethings that struck out at me when I glanced at this patch:

1. Logging is only at select call sites (I cannot tell if you’ve covered all call sites).
2. Logging is not in FileSystem::deleteFile, which I expected from the bug title.
3. You log things if deleteNonEmptyDirectory fails, which I didn’t expect from the bug title.
4. The logging does not include an error status, which I expected from the bug title.
5. The logging includes file names, which I didn’t expect from the bug title.
6. Alexey’s point
7. I think the logging is debug only and I’m unclear if that is a large enough audience for us to see thing.
8. I think this may be using the wrong logging mechanism: why not use log channels? ChangeLog message doesn’t explain.
9. ChangeLog message doesn’t explain how this logging makes things easier/what kinds of bugs we are trying to diagnose.

[Kate Cheney]

Created attachment 376314 [details]
Patch

[Brent Fulgham]

Comment on attachment 376314 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=376314&action=review

> Source/WTF/wtf/posix/FileSystemPOSIX.cpp:75
> +    bool unlinkResult = unlink(fsRep.data());

I would propose:

int unlinkResult = unlink(fsRep.data());

Or:

bool unlinked = !unlink(fsRep.data());
if (!unlinked)
    LOG_ERROR(....

return unlinked;

[Kate Cheney]

Created attachment 376321 [details]
Patch

[Alexey Proskuryakov]

Comment on attachment 376314 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=376314&action=review

> Source/WTF/wtf/posix/FileSystemPOSIX.cpp:70
> +        LOG_ERROR("Failed to get filesystem representation to create CString from cfString or filesystem representation is a null value");

I suggest prepending "File failed to delete. " or "Could not delete a file. " to this for some context.

[Kate Cheney]

Created attachment 376332 [details]
Patch

[Brent Fulgham]

Comment on attachment 376332 [details]
Patch

Looks good to me. r=me

[WebKit Commit Bot]

Comment on attachment 376332 [details]
Patch

Clearing flags on attachment: 376332

Committed r248702: <https://trac.webkit.org/changeset/248702>

[WebKit Commit Bot]

All reviewed patches have been landed.  Closing bug.

[Tim Horton]

I'm hitting this a bunch locally... do you want bugs about cases where this logging happens, or what?

[Kate Cheney]

(In reply to Tim Horton from comment #13)
> I'm hitting this a bunch locally... do you want bugs about cases where this
> logging happens, or what?

This doesn't need to be reported. It's for future bugs where the error might be meaningful in the context of the bug.

[Darin Adler]

I think we might eventually need to do something different.

Sometimes something calls "deleteFile" and knows the file might not exist, and does not want that information logged to the console. If the failure is unexpected the logging is more useful. It would be nice to offer a way to log when the failure is unexpected only, even if this makes the code a tiny bit more complex.

Ideally we’d quiet the "hitting it a bunch locally" almost entirely with this technique, then we'd see logs for the unexpected failures.

Function calls that report their failures "directly to the user" are something I consider an anti-pattern. But I think we can cancel that out if we distinguish the expected failures from the unexpected ones.

[Brent Fulgham]

(In reply to Tim Horton from comment #13)
> I'm hitting this a bunch locally... do you want bugs about cases where this
> logging happens, or what?

If this logging is getting spammy we might want to make it an INFO level log entry.

It would be interesting to know why the delete is failing, and whether it makes sense to call delete for that call stack, or whether we should be taking some action when the delete fails.

We might need to pass a flag indicating that failure is expected/normal in some cases, and not log when that happens.

[Kate Cheney]

I could add a parameter to the deleteFile function that defaults to "never log." Then in the places where it is important (like the places I put the logging in the original patch upload, i.e. places where !FileSystem::deleteFile() is included in the code), I could set the parameter to "always log." Then any additional places we find along the way where logging might be helpful can also use the parameter as needed. Does that sound okay?

[Darin Adler]

I think something like that is good. But maybe the default could go the other way. The callers that expect errors could indicate that they expect them.

However, I wouldn’t want the logging to ignore *all* errors, just the specific error that is expected. So the goal for the argument would be to say what error is expected.

[Kate Cheney]

I agree. So, to summarize, the default would be to always log. Then the caller passes an argument to indicate any errors they expect that then won't be logged. 

One idea is the argument could be value(s) chosen from an enum of potential error codes of the unlink() function. I could also add in comments next to each code to ensure people know the correct code for the expected error, for ex, ENOENT is the "no such file or directory" error). If anyone has other ideas, I'd be happy to hear them too.

[Darin Adler]

Yes, I think it should be an OptionSet of expected errors, but not literally POSIX errors like ENOENT since the point of FileSystem is to abstract away details of the operating system. So an OptionSet that expresses the types of errors that are expected, probably using an enumeration. We’d add them as we need new concepts.

I assume one value in the enumeration would be "it's OK if the file doesn't exist". Not sure which others we’d find we need.

[Darin Adler]

Not exactly "expected errors" but "unsurprising errors, which we should ignore silently without logging".

[Simon Fraser (smfr)]

Now every layout test logs:

12:46:33.026 12287   ERROR: File failed to delete. Error message: No such file or directory
12:46:33.026 12287   /Volumes/Data/Development/system/webkit/OpenSource/Source/WTF/wtf/posix/FileSystemPOSIX.cpp(77) : bool WTF::FileSystemImpl::deleteFile(const WTF::String &)
12:46:33.026 12287   ERROR: File failed to delete. Error message: No such file or directory
12:46:33.026 12287   /Volumes/Data/Development/system/webkit/OpenSource/Source/WTF/wtf/posix/FileSystemPOSIX.cpp(77) : bool WTF::FileSystemImpl::deleteFile(const WTF::String &)
12:46:33.026 12287   ERROR: File failed to delete. Error message: No such file or directory
12:46:33.026 12287   /Volumes/Data/Development/system/webkit/OpenSource/Source/WTF/wtf/posix/FileSystemPOSIX.cpp(77) : bool WTF::FileSystemImpl::deleteFile(const WTF::String &)
12:46:33.026 12287   ERROR: File failed to delete. Error message: No such file or directory
12:46:33.026 12287   /Volumes/Data/Development/system/webkit/OpenSource/Source/WTF/wtf/posix/FileSystemPOSIX.cpp(77) : bool WTF::FileSystemImpl::deleteFile(const WTF::String &)
12:46:33.026 12287   ERROR: File failed to delete. Error message: No such file or directory
12:46:33.026 12287   /Volumes/Data/Development/system/webkit/OpenSource/Source/WTF/wtf/posix/FileSystemPOSIX.cpp(77) : bool WTF::FileSystemImpl::deleteFile(const WTF::String &)
12:46:33.026 12287   ERROR: File failed to delete. Error message: No such file or directory
12:46:33.026 12287   /Volumes/Data/Development/system/webkit/OpenSource/Source/WTF/wtf/posix/FileSystemPOSIX.cpp(77) : bool WTF::FileSystemImpl::deleteFile(const WTF::String &)
12:46:33.026 12287   ERROR: File failed to delete. Error message: No such file or directory
12:46:33.026 12287   /Volumes/Data/Development/system/webkit/OpenSource/Source/WTF/wtf/posix/FileSystemPOSIX.cpp(77) : bool WTF::FileSystemImpl::deleteFile(const WTF::String &)