JFFS2 : non-existent inode

JFFS2 : non-existent inode

[AMUL KUMAR SAHA]

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

Re: JFFS2 : non-existent inode

[David Woodhouse]

On Wed, 2009-03-04 at 05:43 +0000, AMUL KUMAR SAHA wrote:
> 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.

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?

> 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.

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.

> 3) P1 deletes the inode-cache(f->inocache), and releases the lock.

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?

> 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.

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


> 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.

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

-- 
dwmw2

Re: JFFS2 : non-existent inode

[Amul Kumar Saha]

Hi David,

>> 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.
>
> 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?
>>
>> 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.
>
> 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.
>>
>> 3) P1 deletes the inode-cache(f->inocache), and releases the lock.
>
> 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?
>

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

>> 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.
>
> Hm, can you make that a WARN() and show the backtrace?
>

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 

Re: JFFS2 : non-existent inode

[David Woodhouse]

On Wed, 2009-03-11 at 20:40 +0530, Amul Kumar Saha wrote:
> The following is the LOG, that we got, around the time when we
> encountered the ERROR.

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
David.Woodhouse@intel.com                              Intel Corporation

JFFS2 : non-existent inode

[geraldwalden]

Hello:

Environment : Arm7 custom SBC, linux-2.6.26 

On a select number of our units (in the field) we observe the message "requestied to read an nonexistent ino" after performing a write to the flash and then performing an "ls -al" of the file we just wrote.

I am trying to pick up on the below thread that looks promising - yet has no resolution to it:

http://lists.infradead.org/pipermail/linux-mtd/2009-March/024836.html

Because I am encountering what looks to be the same problem as the above I am assuming I may be encountering the same problem.

Does anyone have any advice for me on how to pick up where the thread leaves off?  It seems to indicate that there was a real bug, or patch that might be necessary, yet after all this time (since the thread was active), I see no further references to the same - or a similar issue.

Am I to assume that a patch was created for this problem?  Is there something more I can add with respect to debug information / tracebacks / dumps / instrumentation to provide more information so I can bring this issue to the forefront again?  

Thanks for providing me with any direction as to how I can bring this issue back up as an active issue.

Jerry