JFFS2 : non-existent inode

Hello David,

Environment : Flex-OneNAND 8Gb, Apollon Board, linux-2.6.26

I have just started with JFFS2 .

We were running fsstress on 5 Boards for 5 Days .
On 2 out of 5 boards, we observed the message "requestied to read an nonexistent ino", On Repetition, the BUG seems to be random.

Dwelled inside the code and thought of a possible scenario for the occurence. I found the following explanation to it, appropriate; to my minimal knowledge :

1) 2 or more processes(say, P1 and P2) handling GC(jffs2_gc_fetch_inode) enter the function jffs2_iget almost together, before getting a mutex_lock.
2) When a request for a lock is raised, one of the processes(P1) gets the mutex_lock(&f->sem) and the other one waits.
3) P1 deletes the inode-cache(f->inocache), and releases the lock.
4) Now, when P2 ends up calling jffs2_do_read_inode with 'inode->ino' available locally in that function (unaware of the fact that, this particular inode was just destroyed).
5) JFFS2-Error with the message "requestied to read an nonexistent ino" is displayed.

In the mean time, I have come up with my own fix to this situation. Just wanting to know if my explanation makes sense, so that I can go ahead with posting the patch in mailing-list.

Thanks and Regards,

Amul Kumar Saha
Memory Solutions Group
Samsung India Software Operations

They shouldn't be very close together -- GC is protected by the alloc_sem mutex, and shouldn't be happening concurrently at all. But maybe it's one thread doing GC while another thread is actually trying to open the inode in question for real?

It uses iget_locked(). The first caller will get a _locked_ inode with the I_NEW bit set. It will go ahead and fill in the inode appropriately, then call unlock_new_inode() to clear the I_NEW bit and unlock the inode.

Then the second caller will return from iget_locked(). The I_NEW bit won't be set, and it'll return immediately. So I don't think your scenario is possible.

Why would it delete the inode-cache? Doesn't that only ever happen in GC when the final physical node of the inode has been deleted from the medium?

Hm, can you make that a WARN() and show the backtrace?

You might be close, but I'm not convinced you have it exactly right.

dwmw2

Hi David,

Thanks for adding to my knowledge. It would be of great help.

I have put a WARN(), just before the print message, "requestied to read an nonexistent ino", and I'm trying to get a backtrace.
Since, the BUG is random, we would have to wait for few days.

The following is the LOG, that we got, around the time when we encountered the ERROR.

JFFS2 error: (245) jffs2_do_read_inode: requestied to read an nonexistent ino 14979433
JFFS2 error: (16442) jffs2_do_read_inode: requestied to read an nonexistent ino 14979147
JFFS2 error: (245) jffs2_do_read_inode: requestied to read an nonexistent ino 14979433
iget() failed for ino #14979147
JFFS2 error: (16442) jffs2_do_read_inode: requestied to read an nonexistent ino 14979659
iget() failed for ino #14979659
rm: unable to remove `/tmp/p0/d3/d25/d28/d30/d50/d24b/dcc9/d193/d203/d2ee/d384/dafe/d299/d341/d4fd/d77b/d196/d187': Directory not empty
rm: unable to remove `/tmp/p0/d3/d25/d28/d30/d50/d24b/dcc9/d193/d203/d2ee/d384/dafe/d299/d341/d4fd/d77b/d196': Directory not empty
rm: unable to stat `/tmJFFS2 error: (16442) jffs2_do_read_inode: requestied to read an nonexistent ino 14979147 p/p0/d3/d25/d28/d30/d50/d24b/dccJFFS2 error: (245) jffs2_do_read_inode: requestied to read an nonexistent ino 14979433 9/d193/d203/d2ee/d384/dafe/d299/iget() failed for ino #14979147
d341/d4fd/d77b/d257/ff3': Input/output error
rm: unable to remove `/tmp/p0/d3/d25/d28/d30/d50/d24b/dcc9/d193/d203/d2ee/d384/dafe/d299/d341/d4fd/d77b/d257': Directory not empty
rm: unable to remove `/tmp/p0/d3/d25/d28/d30/d50/d24b/dcc9/d193/d203/d2ee/d384/dafe/d299/d341/d4fd/d77b': Dire JFFS2 error: (245) jffs2_do_read_inode: requestied to read an nonexistent ino 14979433
ctory not empty
rm: unable to remove `/tmp/p0/d3/d25/d28/d30/d50/d24b/dcc9/d193/d203/d2ee/d384/dafe/d299/d341/d4fd': Directory not empty
rm: unable to remove `/tmp/p0/d3/d25/d28/d30/d50/d24b/dcc9/d193/d203/d2ee/d384/dafe/d299/d341': Directory not empty
rm: unable to remove `/tmp/p0/d3/d25/d28/d30/d50/d24b/dcc9/d193/d203/d2ee/d384/dafe/d299': Directory not empty
rm: unable to remove `/tmp/p0/d3/d25/d28/d30/d50/d24b/dcc9/d193/d203/d2ee/d384/dafe': Directory not empty
rm: unable to remove `/tmp/p0/d3/d25/JFFS2 error: (245) jffs2_do_read_inode: requestied to read an nonexistent ino 14979433 d28/d30/d50/d24b/dcc9/d193/d203/d2ee/d384': Directory not empty
rm: unable to remove `/tmp/p0/d3/d25/d28/d30/d50/d24b/dcc9/d193/d203/d2ee': Directory not empty
rm: unable to remove `/tmp/p0/d3/d25/d28/d30/d50/d24b/dcc9/d193/d203': Directory not empty
rmJFFS2 error: (245) jffs2_do_read_inode: requestied to read an nonexistent ino 14979433
unable to remove `/tmp/p0/d3/d25/d28/d30/d50/d24b/dcc9/d193': Directory not empty
rm: unable to remove `/tmp/p0/d3/d25/d28/d30/d50/d24b/dcc9': Directory not empty
rm: unable to remove `/tmp/p0/d3/d25/d28/d30/d50/d24b': Directory not empty
rm: unable tJFFS2 error: (245) jffs2_do_read_inode: requestied to read an nonexistent ino 14979433
Count : 22418, Log : 2008-10-15 07:57:42:00 : o remove `/tmp/p0/d3/d25/d28/d30/d50': Directory not empty
rm: unable to remove `/tmp/p0/d3/d25/d28/d30': Directory not empty
rm: unable to remove `/tmp/p0/d3/d25/d28': Directory not empty
rm: unable to remove `/tmp/p0/d3/d25': Directory not empty
rm: unable to remove `/tmp/p0/d3/d1b/d39/d1d2/d25b': Directory not empty
rm: unable to remove `/tmp/p0/d3/d1b/d39/d1d2': Directory not empty
rm: unable to remove `/tmp/p0/d3/d1b/d39': Directory not empty
rm: unable to remove `/tmp/p0/d3/d1b': Directory not empty
rm: unable to remove `/tmJFFS2 error: (245) jffs2_do_read_inode: requestied to read an nonexistent ino 14979433 p/p0/d3': Directory not empty
JFFS2 error: (245) jffs2_do_read_inode: requestied to read an nonexistent ino 14979433
JFFS2 error: (245) jffs2_do_read_inode: requestied to read an nonexistent ino 14979433
JFFS2 error: (245) jffs2_do_read_inode: requestied to read an nonexistent ino 14979433
JFFS2 error: (245) jffs2_do_read_inode: requestied to read an nonexistent ino 14979433
JFFS2 error: (245) jffs2_do_read_inode: requestied to read an nonexistent ino 14979433
JFFS2 error: (245) jffs2_do_read_inode: requestied to read an nonexistent ino 14979433
JFFS2 error: (245) jffs2_do_read_inode: requestied to read an nonexistent ino 14979433
JFFS2 error: (245) jffs2_do_read_inode: requestied to read an nonexistent ino 14979433
JFFS2 error: (245) jffs2_do_read_inode: requestied to read an nonexistent ino 14979433
JFFS2 error: (245) jffs2_do_read_inode: requestied to read an nonexistent ino 14979433
JFFS2 error: (245) jffs2_do_read_inode: requestied to read an nonexistent ino 14979433
JFFS2 error: (245) jffs2_do_read_inode: requestied to read an nonexistent ino 14979433
JFFS2 error: (245) jffs2_do_read_inode: requestied to read an nonexistent ino 14979433
JFFS2 error: (84) jffs2_do_read_inode: requestied to read an nonexistent ino 14979433
JFFS2 error: (245) jffs2_do_read_inode: requestied to read an nonexistent ino 14979433
rm: unable to remove `/tmp/p0': DireJFFS2 error: (16442) jffs2_do_read_inode: requestied to read an nonexistent ino 14979019 ctory not empty
iget() failed for ino #14979019
JFFS2 error: (245) jffs2_do_read_inode: requestied to read an nonexistent ino 14979433
JFFS2 error: (245) jffs2_do_read_inode: requestied to read an nonexistent ino 14979433

Thanks and Regards,
Amul Kumar Saha

Presumably pid 245 is the GC dæmon? What's PID 84? And 16442?

It looks like it's a race between deletion and GC; I'll take a closer look. Thanks.

David Woodhouse                            Open Source Technology Centre
[email protected]                              Intel Corporation