1437011 - Extremely spammy warning |WARNING: (debug) Error: Source()->Close() returned error (rv1) in bsBuffedInputStream::Close().: file [snip]/netwerk/base/nsBufferedStreams.cpp, line 335|

Status: RESOLVED FIXED

(Core :: Networking, defect)

Description

[Jorg K (CEST = GMT+2)]

I see more than 1000 of these in this log:
https://public-artifacts.taskcluster.net/RV33ONdNRIGSpjU8xZKV7Q/0/public/logs/live_backing.log of 2018-02-08T22:34:53.743Z
M-C rev c5120bcaf7bdcb5cdb06a02b60bd5bfe6a

Not present 2018-02-08T13:13:54.751Z
https://public-artifacts.taskcluster.net/Imbx7EaYRcGy_Cn-K1Bo2Q/0/public/logs/live_backing.log
M-C rev 0ac953fcddf10132eaecdb753d72b2ba5a

https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=0ac953fcddf10132eaecdb753d72b2ba5a&tochange=c5120bcaf7bdcb5cdb06a02b60bd5bfe6a

This must be due to recent changes in Netwerk, most likely bug 1371699 (or bug 1405974).

Note that the debug statement
https://searchfox.org/mozilla-central/rev/a5abf843f8fac8530aa5de6fb40e16547bb4a47a/netwerk/base/nsBufferedStreams.cpp#335
was introduced in January 2017 and I have not seen it being triggered before. So something unexpected is happening now.

Comment 1

[Jorg K (CEST = GMT+2)]

OK, those logs were TB logs, but it also happens for FF:
https://public-artifacts.taskcluster.net/K8HcS4RpQ7er4RBljlNkRQ/0/public/logs/live_backing.log
from this job for example:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&revision=d49553765a743ebbd4f08e92a93c9d811ee064c2&selectedJob=161294133

Comment 2

[Andrea Marchesini [:baku]]

Attachment: close.patch

Comment 3

[Nathan Froyd [:froydnj]]

Comment on attachment 8949781 [details] [diff] [review]
close.patch

Review of attachment 8949781 [details] [diff] [review]:
-----------------------------------------------------------------

I can't find any documentation about what to do here; returning NS_BASE_STREAM_CLOSED seems good, but NS_OK is probably allowed and also reasonable.

::: xpcom/io/NonBlockingAsyncInputStream.cpp
@@ +123,5 @@
>    {
>      MutexAutoLock lock(mLock);
>  
>      if (mClosed) {
> +      return NS_OK;

A short (one-line) comment about why we're not throwing an error here would be appropriate, I think.  I can't think of a good short explanation, though.  WDYT?

Comment 4

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/e7cb93b3076f
NonBlockingAsyncInputStream::Close() should return NS_OK if already closed, r=froydnj

Comment 6

[Bogdan Tara[:bogdan_tara | bogdant]]

https://hg.mozilla.org/mozilla-central/rev/e7cb93b3076f

Comment 7

[ISHIKAWA, Chiaki]

Hi,

-      return NS_BASE_STREAM_CLOSED;
+      // Here we could return NS_BASE_STREAM_CLOSED as well, but just to avoid
+      // warning messages, let's make everybody happy with a NS_OK.
+      return NS_OK;

I don't have the man-power right now to investigate the flawed logic somewhere, but
as an author of the DEBUG print of the warning messages,
I believe the correct action is to avoid the Close() for already closed stream WITHIN
mozilla I/O wrapper OR if it is the application that calls Close() against already closed stream, then the application
needs to be fixed.

The reason I inserted the warning because C-C TB had a flawed logic regarding stream handling.
 It had a tendency of closing already closed file streams (during mail download error handling.)
keeping open stream when it could have closed the stream (a no longer needed open stream fails renaming/deletion of files under Windows).
Interesting thing is TB closes streams more than twice (due to flawed logic) and got NS_BASE_STREAM_CLOSED during ERROR processing.
So the code did not bother to check the return value of |Close|, which was a fatal mistake.
|Close| can return a fresh error due to file system overflow, file system fault (including network error of remote file system).
These errors were not handled at all in TB and I am struggling to insert better checks to TB.
TB obviously WRITE MUCH MORE DATA than FF. 

While trying to fix the Close issue of C-C TB during error procesing, I noticed that I/O wrapper failed many checks for failing |Close| operation (Close may cause buffered output for buffered output stream, file meta system update, etc.: all these can fail due to file system overflow, file system error, network error in the case of remotely mounted file system).

Thanks to the warning, I was glad that I could fix TB's logical flaw which was found in the error handling of message download failures due to I/O errors (I simulated network error of remotely mounted filesystem).

However, that debugging efforts hinged on the fact that Close() returned NS_ERROR_BASE_STREAM_CLOSED for an already closed stream.
Now if this is changed.
I am not sure if it is a good idea.

But again, right now, I have no time to dive into the logic of why this warning is now triggered so often.

TIA

Comment 8

[Honza Bambas (:mayhemer)]

I have to agree with Ishikawa, at least to some extent.  I think we should either of:

- not set mClose = true sooner than we actually perform the close successfully with mInputStream->Close().  Question is, how does different OSes behave when you try to close a file again when previous close has failed.  That could be inconsistent and lead to unpredictable behavior and coding obstacles.  

- have a nsresult mCloseStatus, assign it with mInputStream->Close() and return it from NonBlockingAsyncInputStream::Close() when mClosed == true (leave mClosed = true where it is).

I'm not sure how valid is to use the NS_ERROR_BASE_STREAM_CLOSED for whatever fixes in C-C - can you please provide an example?

Comment 9

[ISHIKAWA, Chiaki]

(In reply to Honza Bambas (:mayhemer) from comment #8)
> I have to agree with Ishikawa, at least to some extent.  I think we should
> either of:
> 
> - not set mClose = true sooner than we actually perform the close
> successfully with mInputStream->Close().  Question is, how does different
> OSes behave when you try to close a file again when previous close has
> failed.  That could be inconsistent and lead to unpredictable behavior and
> coding obstacles.  
> 
> - have a nsresult mCloseStatus, assign it with mInputStream->Close() and
> return it from NonBlockingAsyncInputStream::Close() when mClosed == true
> (leave mClosed = true where it is).
> 
> I'm not sure how valid is to use the NS_ERROR_BASE_STREAM_CLOSED for
> whatever fixes in C-C - can you please provide an example?

Thank you for your encouraging comment.

I am not sure if I explained my reason very well.
Here is the gist. (I can give a code example or two later, but looking at the local patch, the explanation would be long.)

- C-C TB failed to check the return value of |Close()| for whatever reason. The failure to check the error return of low-level I/O primitives is rampant in mozilla code base, and that could be the ereason.

- I have been trying to fix this so that I can use buffered output for writing downloaded message USING BUFFERING (right, TB does not use buffered output today. It merrily runs happily calling write system call for EVERY SINGLE LINE of message!).
When buffered output is used, |Close()| may trigger a |Flush()| which results in file write error (file system filling up, remote file server is inaccessible due to temporary network outage, etc.).
So we should detect the error return from |Close()|. Every single message is a precious data for a mail client.

So I inserted the check for |Close()| naively for the first step of enabling buffered output. 
Immediately, I saw NS_BASE_STREAM_CLOSED during nominal testing. I investigated why.
The reason, basically, is the flawed logic/coding in error recovery. C-C TB code was not tracking the file stream status correctly. Low-level routine for message downloading closes output stream when it detects error, but but the information is not passed around, and the top-level routine
always closes file stream even when the lower-level routine encountered an error and closed the stream already.

In this sense, that |Close()| returns NS_ERROR_BASE_STREAM_CLOSED is very important for me (or to anybody else) to analyze the not-so-well-documented C-C TB's file handling and uncovering logical/coding error.

After figuring out the reason and correcting the flawed logic/coding, I saw the primitive error recovery then: I am not sure if it worked before.

After the debugging/correction, I came up with another
theory why the return value of |Close()| was not checked.,
I think failing to figure out the file stream status in detail even in the face of download and other errors resulted in the INTENTIONAL omission of |Close()| because,
even in the usual case of handling downloading errors which are tested in test suite, |Close()| at the top-level routine returns NS_BASE_STREAM_CLOSED loud and clear, and it took me a few weeks to figure out the flawed coding/logic a few years ago.
In the past, maybe somebody tried to insert the check for the return value of |Close()| but because of the mysterious NS__BASE_STREAM_CLOSED in the normal handling of download errors, those people probably gave up prematurely.
(Of course the general tendency to ignore low-level I/O routine's error status may play a role here).

But as I explained, now |Close()| needs to be checked for error return when I enable buffered output.
The code needed to be cleaned up because handling NS_BASE_STREAM_CLOSED error as a special case for error value of |Close()| was a maintenance nightmare. The cleaning up was a good thing IMHO.
 
So to me, |Close()| returning NS_OK for already closed stream is a definite NO, NO. It masks still possibly lurking logical/coding errors in C-C and M-C, possibly. But I suspect C-C TB has a more chance of such errors since it is a few times big in terms of the handling of various data to local storage than M-C FF.

Trying to hide the sloppy coding on the side of the caller of |Close()| is, to me, a flawed approach. It is hiding either the sloppy coding or worse real logical error or coding error.

Also, NS_ERROR_STREAM_CLOSED is used by the existing C-C TB code for returning valid error return code.
That is, there are code snipets, in C-C that returns NS_BASE_STREAM_CLOSED (though, I am not sure how much code, say, third-party addons depend on this.)

If you need, I can give you some code examples, but the explanation needs a few screenful pages, I am afraid.

TIA


PS: You can call me Chiaki, that is my first name. It is not customary to call someone with the first name in Japan: the full name is written Ishikawa Chiaki (Ishikawa, the family name comes first). I wrote "ISHIKAWA,Chiaki" to stress the capitalized part ISHIKAWA before the comma is the family name, but this little trick is not understood very well. Anyway,  I lived in Canada when I was a grad student, and in my line of work, I work with overseas partners and majority of them call me Chiaki. So I am more familiar being called Chiaki :-)

Comment 10

[Honza Bambas (:mayhemer)]

(In reply to ISHIKAWA, Chiaki from comment #9)
> If you need, I can give you some code examples, but the explanation needs a
> few screenful pages, I am afraid.

It would be good, if not that much work.

Other option is to suggest what would work for you particular case the best way - would it be one of the suggestions in comment 8 or something else?


Note that NS_BASE_STREAM_CLOSED is widely used as an indication of a graceful close of an input or output stream all over the platform.  On many places it's treated as NS_OK (or even converted to it.)

But, we return NS_BASE_STREAM_CLOSED from Write/Read(Segments) and Available methods after the stream has been gracefully closed, but not from Close(), AFAICT - would have to look on various Close() implementations, though.  


When a stream is successfully closed (the first call to Close() has succeeded), I don't see a reason to let Close() - and only Close() - return NS_BASE_STREAM_CLOSED afterwords.



> 
> TIA
> 
> 
> PS: You can call me Chiaki, that is my first name. It is not customary to
> call someone with the first name in Japan: the full name is written Ishikawa
> Chiaki (Ishikawa, the family name comes first). I wrote "ISHIKAWA,Chiaki" to
> stress the capitalized part ISHIKAWA before the comma is the family name,
> but this little trick is not understood very well. Anyway,  I lived in
> Canada when I was a grad student, and in my line of work, I work with
> overseas partners and majority of them call me Chiaki. So I am more familiar
> being called Chiaki :-)

I had a suspicion :)  Hi, Chiaki :)