[PATCH] ceph: fix dout logs for null pointers

[PATCH] ceph: fix dout logs for null pointers

[xiubli]

From: Xiubo Li <xiubli@redhat.com>

For example, if dentry and inode is NULL, the log will be:
ceph:  lookup result=000000007a1ca695
ceph:  submit_request on 0000000041d5070e for inode 000000007a1ca695

The will be confusing without checking the corresponding code carefully.

Signed-off-by: Xiubo Li <xiubli@redhat.com>
---
 fs/ceph/dir.c        | 2 +-
 fs/ceph/mds_client.c | 6 +++++-
 2 files changed, 6 insertions(+), 2 deletions(-)

diff --git a/fs/ceph/dir.c b/fs/ceph/dir.c
index ffeaff5bf211..245a262ec198 100644
--- a/fs/ceph/dir.c
+++ b/fs/ceph/dir.c
@@ -798,7 +798,7 @@ static struct dentry *ceph_lookup(struct inode *dir, struct dentry *dentry,
 	err = ceph_handle_snapdir(req, dentry, err);
 	dentry = ceph_finish_lookup(req, dentry, err);
 	ceph_mdsc_put_request(req);  /* will dput(dentry) */
-	dout("lookup result=%p\n", dentry);
+	dout("lookup result=%d\n", err);
 	return dentry;
 }
 
diff --git a/fs/ceph/mds_client.c b/fs/ceph/mds_client.c
index b6aa357f7c61..e34f159d262b 100644
--- a/fs/ceph/mds_client.c
+++ b/fs/ceph/mds_client.c
@@ -2772,7 +2772,11 @@ int ceph_mdsc_submit_request(struct ceph_mds_client *mdsc, struct inode *dir,
 		ceph_get_cap_refs(ceph_inode(req->r_old_dentry_dir),
 				  CEPH_CAP_PIN);
 
-	dout("submit_request on %p for inode %p\n", req, dir);
+	if (dir)
+		dout("submit_request on %p for inode %p\n", req, dir);
+	else
+		dout("submit_request on %p\n", req);
+
 	mutex_lock(&mdsc->mutex);
 	__register_request(mdsc, req, dir);
 	__do_request(mdsc, req);
-- 
2.21.0

Re: [PATCH] ceph: fix dout logs for null pointers

[Jeff Layton]

On Mon, 2020-02-17 at 06:28 -0500, xiubli@redhat.com wrote:
> From: Xiubo Li <xiubli@redhat.com>
> 
> For example, if dentry and inode is NULL, the log will be:
> ceph:  lookup result=000000007a1ca695
> ceph:  submit_request on 0000000041d5070e for inode 000000007a1ca695
> 
> The will be confusing without checking the corresponding code carefully.
> 
> Signed-off-by: Xiubo Li <xiubli@redhat.com>
> ---
>  fs/ceph/dir.c        | 2 +-
>  fs/ceph/mds_client.c | 6 +++++-
>  2 files changed, 6 insertions(+), 2 deletions(-)
> 
> diff --git a/fs/ceph/dir.c b/fs/ceph/dir.c
> index ffeaff5bf211..245a262ec198 100644
> --- a/fs/ceph/dir.c
> +++ b/fs/ceph/dir.c
> @@ -798,7 +798,7 @@ static struct dentry *ceph_lookup(struct inode *dir, struct dentry *dentry,
>  	err = ceph_handle_snapdir(req, dentry, err);
>  	dentry = ceph_finish_lookup(req, dentry, err);
>  	ceph_mdsc_put_request(req);  /* will dput(dentry) */
> -	dout("lookup result=%p\n", dentry);
> +	dout("lookup result=%d\n", err);
>  	return dentry;
>  }
>  

The existing error handling in this function is really hard to follow
(the way that "err" is passed to subsequent functions). It really took
me a minute to figure out whether this change would make sense for all
the cases. I think it does, but it might be nice to do a larger
reorganization of this code if you're interested in improving it.

> diff --git a/fs/ceph/mds_client.c b/fs/ceph/mds_client.c
> index b6aa357f7c61..e34f159d262b 100644
> --- a/fs/ceph/mds_client.c
> +++ b/fs/ceph/mds_client.c
> @@ -2772,7 +2772,11 @@ int ceph_mdsc_submit_request(struct ceph_mds_client *mdsc, struct inode *dir,
>  		ceph_get_cap_refs(ceph_inode(req->r_old_dentry_dir),
>  				  CEPH_CAP_PIN);
>  
> -	dout("submit_request on %p for inode %p\n", req, dir);
> +	if (dir)
> +		dout("submit_request on %p for inode %p\n", req, dir);
> +	else
> +		dout("submit_request on %p\n", req);
> +
>  	mutex_lock(&mdsc->mutex);
>  	__register_request(mdsc, req, dir);
>  	__do_request(mdsc, req);


I'll merge into testing later today.
-- 
Jeff Layton <jlayton@kernel.org>

Re: [PATCH] ceph: fix dout logs for null pointers

[Xiubo Li]

On 2020/2/17 20:25, Jeff Layton wrote:
> On Mon, 2020-02-17 at 06:28 -0500, xiubli@redhat.com wrote:
>> From: Xiubo Li <xiubli@redhat.com>
>>
>> For example, if dentry and inode is NULL, the log will be:
>> ceph:  lookup result=000000007a1ca695
>> ceph:  submit_request on 0000000041d5070e for inode 000000007a1ca695
>>
>> The will be confusing without checking the corresponding code carefully.
>>
>> Signed-off-by: Xiubo Li <xiubli@redhat.com>
>> ---
>>   fs/ceph/dir.c        | 2 +-
>>   fs/ceph/mds_client.c | 6 +++++-
>>   2 files changed, 6 insertions(+), 2 deletions(-)
>>
>> diff --git a/fs/ceph/dir.c b/fs/ceph/dir.c
>> index ffeaff5bf211..245a262ec198 100644
>> --- a/fs/ceph/dir.c
>> +++ b/fs/ceph/dir.c
>> @@ -798,7 +798,7 @@ static struct dentry *ceph_lookup(struct inode *dir, struct dentry *dentry,
>>   	err = ceph_handle_snapdir(req, dentry, err);
>>   	dentry = ceph_finish_lookup(req, dentry, err);
>>   	ceph_mdsc_put_request(req);  /* will dput(dentry) */
>> -	dout("lookup result=%p\n", dentry);
>> +	dout("lookup result=%d\n", err);
>>   	return dentry;
>>   }
>>   
> The existing error handling in this function is really hard to follow
> (the way that "err" is passed to subsequent functions). It really took
> me a minute to figure out whether this change would make sense for all
> the cases. I think it does, but it might be nice to do a larger
> reorganization of this code if you're interested in improving it.

yeah, sure I will do it later.

Thanks.


>> diff --git a/fs/ceph/mds_client.c b/fs/ceph/mds_client.c
>> index b6aa357f7c61..e34f159d262b 100644
>> --- a/fs/ceph/mds_client.c
>> +++ b/fs/ceph/mds_client.c
>> @@ -2772,7 +2772,11 @@ int ceph_mdsc_submit_request(struct ceph_mds_client *mdsc, struct inode *dir,
>>   		ceph_get_cap_refs(ceph_inode(req->r_old_dentry_dir),
>>   				  CEPH_CAP_PIN);
>>   
>> -	dout("submit_request on %p for inode %p\n", req, dir);
>> +	if (dir)
>> +		dout("submit_request on %p for inode %p\n", req, dir);
>> +	else
>> +		dout("submit_request on %p\n", req);
>> +
>>   	mutex_lock(&mdsc->mutex);
>>   	__register_request(mdsc, req, dir);
>>   	__do_request(mdsc, req);
>
> I'll merge into testing later today.

Re: [PATCH] ceph: fix dout logs for null pointers

[Ilya Dryomov]

On Mon, Feb 17, 2020 at 12:28 PM <xiubli@redhat.com> wrote:
>
> From: Xiubo Li <xiubli@redhat.com>
>
> For example, if dentry and inode is NULL, the log will be:
> ceph:  lookup result=000000007a1ca695
> ceph:  submit_request on 0000000041d5070e for inode 000000007a1ca695
>
> The will be confusing without checking the corresponding code carefully.
>
> Signed-off-by: Xiubo Li <xiubli@redhat.com>
> ---
>  fs/ceph/dir.c        | 2 +-
>  fs/ceph/mds_client.c | 6 +++++-
>  2 files changed, 6 insertions(+), 2 deletions(-)
>
> diff --git a/fs/ceph/dir.c b/fs/ceph/dir.c
> index ffeaff5bf211..245a262ec198 100644
> --- a/fs/ceph/dir.c
> +++ b/fs/ceph/dir.c
> @@ -798,7 +798,7 @@ static struct dentry *ceph_lookup(struct inode *dir, struct dentry *dentry,
>         err = ceph_handle_snapdir(req, dentry, err);
>         dentry = ceph_finish_lookup(req, dentry, err);
>         ceph_mdsc_put_request(req);  /* will dput(dentry) */
> -       dout("lookup result=%p\n", dentry);
> +       dout("lookup result=%d\n", err);
>         return dentry;
>  }
>
> diff --git a/fs/ceph/mds_client.c b/fs/ceph/mds_client.c
> index b6aa357f7c61..e34f159d262b 100644
> --- a/fs/ceph/mds_client.c
> +++ b/fs/ceph/mds_client.c
> @@ -2772,7 +2772,11 @@ int ceph_mdsc_submit_request(struct ceph_mds_client *mdsc, struct inode *dir,
>                 ceph_get_cap_refs(ceph_inode(req->r_old_dentry_dir),
>                                   CEPH_CAP_PIN);
>
> -       dout("submit_request on %p for inode %p\n", req, dir);
> +       if (dir)
> +               dout("submit_request on %p for inode %p\n", req, dir);
> +       else
> +               dout("submit_request on %p\n", req);

Hi Xiubo,

It's been this way for a couple of years now.  There are a lot more
douts in libceph, ceph and rbd that are sometimes fed NULL pointers.
I don't think replacing them with conditionals is the way forward.

I honestly don't know what security concern is addressed by hashing
NULL pointers, but that is what we have...  Ultimately, douts are just
for developers, and when you find yourself having to chase individual
pointers, you usually have a large enough piece of log to figure out
what the NULL hash is.

Thanks,

                Ilya

Re: [PATCH] ceph: fix dout logs for null pointers

[Xiubo Li]

On 2020/2/17 22:52, Ilya Dryomov wrote:
> On Mon, Feb 17, 2020 at 12:28 PM <xiubli@redhat.com> wrote:
>> From: Xiubo Li <xiubli@redhat.com>
>>
>> For example, if dentry and inode is NULL, the log will be:
>> ceph:  lookup result=000000007a1ca695
>> ceph:  submit_request on 0000000041d5070e for inode 000000007a1ca695
>>
>> The will be confusing without checking the corresponding code carefully.
>>
>> Signed-off-by: Xiubo Li <xiubli@redhat.com>
>> ---
>>   fs/ceph/dir.c        | 2 +-
>>   fs/ceph/mds_client.c | 6 +++++-
>>   2 files changed, 6 insertions(+), 2 deletions(-)
>>
>> diff --git a/fs/ceph/dir.c b/fs/ceph/dir.c
>> index ffeaff5bf211..245a262ec198 100644
>> --- a/fs/ceph/dir.c
>> +++ b/fs/ceph/dir.c
>> @@ -798,7 +798,7 @@ static struct dentry *ceph_lookup(struct inode *dir, struct dentry *dentry,
>>          err = ceph_handle_snapdir(req, dentry, err);
>>          dentry = ceph_finish_lookup(req, dentry, err);
>>          ceph_mdsc_put_request(req);  /* will dput(dentry) */
>> -       dout("lookup result=%p\n", dentry);
>> +       dout("lookup result=%d\n", err);
>>          return dentry;
>>   }
>>
>> diff --git a/fs/ceph/mds_client.c b/fs/ceph/mds_client.c
>> index b6aa357f7c61..e34f159d262b 100644
>> --- a/fs/ceph/mds_client.c
>> +++ b/fs/ceph/mds_client.c
>> @@ -2772,7 +2772,11 @@ int ceph_mdsc_submit_request(struct ceph_mds_client *mdsc, struct inode *dir,
>>                  ceph_get_cap_refs(ceph_inode(req->r_old_dentry_dir),
>>                                    CEPH_CAP_PIN);
>>
>> -       dout("submit_request on %p for inode %p\n", req, dir);
>> +       if (dir)
>> +               dout("submit_request on %p for inode %p\n", req, dir);
>> +       else
>> +               dout("submit_request on %p\n", req);
> Hi Xiubo,
>
> It's been this way for a couple of years now.  There are a lot more
> douts in libceph, ceph and rbd that are sometimes fed NULL pointers.
> I don't think replacing them with conditionals is the way forward.
>
> I honestly don't know what security concern is addressed by hashing
> NULL pointers, but that is what we have...  Ultimately, douts are just
> for developers, and when you find yourself having to chase individual
> pointers, you usually have a large enough piece of log to figure out
> what the NULL hash is.

Hi Ilya

For the ceph_lookup(). The dentry will be NULL(when the directory exists 
or -ENOENT) or ERR_PTR(-errno) in most cases here, it seems for the 
rename case it will be the old dentry returned.

So today I was trying to debug and get some logs from it, the 
000000007a1ca695 really confused me for a long time before I dig into 
the source code.

Thanks,

> Thanks,
>
>                  Ilya
>

Re: [PATCH] ceph: fix dout logs for null pointers

[Ilya Dryomov]

On Mon, Feb 17, 2020 at 4:02 PM Xiubo Li <xiubli@redhat.com> wrote:
>
> On 2020/2/17 22:52, Ilya Dryomov wrote:
> > On Mon, Feb 17, 2020 at 12:28 PM <xiubli@redhat.com> wrote:
> >> From: Xiubo Li <xiubli@redhat.com>
> >>
> >> For example, if dentry and inode is NULL, the log will be:
> >> ceph:  lookup result=000000007a1ca695
> >> ceph:  submit_request on 0000000041d5070e for inode 000000007a1ca695
> >>
> >> The will be confusing without checking the corresponding code carefully.
> >>
> >> Signed-off-by: Xiubo Li <xiubli@redhat.com>
> >> ---
> >>   fs/ceph/dir.c        | 2 +-
> >>   fs/ceph/mds_client.c | 6 +++++-
> >>   2 files changed, 6 insertions(+), 2 deletions(-)
> >>
> >> diff --git a/fs/ceph/dir.c b/fs/ceph/dir.c
> >> index ffeaff5bf211..245a262ec198 100644
> >> --- a/fs/ceph/dir.c
> >> +++ b/fs/ceph/dir.c
> >> @@ -798,7 +798,7 @@ static struct dentry *ceph_lookup(struct inode *dir, struct dentry *dentry,
> >>          err = ceph_handle_snapdir(req, dentry, err);
> >>          dentry = ceph_finish_lookup(req, dentry, err);
> >>          ceph_mdsc_put_request(req);  /* will dput(dentry) */
> >> -       dout("lookup result=%p\n", dentry);
> >> +       dout("lookup result=%d\n", err);
> >>          return dentry;
> >>   }
> >>
> >> diff --git a/fs/ceph/mds_client.c b/fs/ceph/mds_client.c
> >> index b6aa357f7c61..e34f159d262b 100644
> >> --- a/fs/ceph/mds_client.c
> >> +++ b/fs/ceph/mds_client.c
> >> @@ -2772,7 +2772,11 @@ int ceph_mdsc_submit_request(struct ceph_mds_client *mdsc, struct inode *dir,
> >>                  ceph_get_cap_refs(ceph_inode(req->r_old_dentry_dir),
> >>                                    CEPH_CAP_PIN);
> >>
> >> -       dout("submit_request on %p for inode %p\n", req, dir);
> >> +       if (dir)
> >> +               dout("submit_request on %p for inode %p\n", req, dir);
> >> +       else
> >> +               dout("submit_request on %p\n", req);
> > Hi Xiubo,
> >
> > It's been this way for a couple of years now.  There are a lot more
> > douts in libceph, ceph and rbd that are sometimes fed NULL pointers.
> > I don't think replacing them with conditionals is the way forward.
> >
> > I honestly don't know what security concern is addressed by hashing
> > NULL pointers, but that is what we have...  Ultimately, douts are just
> > for developers, and when you find yourself having to chase individual
> > pointers, you usually have a large enough piece of log to figure out
> > what the NULL hash is.
>
> Hi Ilya
>
> For the ceph_lookup(). The dentry will be NULL(when the directory exists
> or -ENOENT) or ERR_PTR(-errno) in most cases here, it seems for the
> rename case it will be the old dentry returned.
>
> So today I was trying to debug and get some logs from it, the
> 000000007a1ca695 really confused me for a long time before I dig into
> the source code.

I was reacting to ceph_mdsc_submit_request() hunk.  Feel free to tweak
ceph_lookup() or refactor it so that err is not threaded through three
different functions as Jeff suggested.

Thanks,

                Ilya

Re: [PATCH] ceph: fix dout logs for null pointers

[Xiubo Li]

On 2020/2/17 23:27, Ilya Dryomov wrote:
> On Mon, Feb 17, 2020 at 4:02 PM Xiubo Li <xiubli@redhat.com> wrote:
>> On 2020/2/17 22:52, Ilya Dryomov wrote:
>>> On Mon, Feb 17, 2020 at 12:28 PM <xiubli@redhat.com> wrote:
>>>> From: Xiubo Li <xiubli@redhat.com>
>>>>
>>>> For example, if dentry and inode is NULL, the log will be:
>>>> ceph:  lookup result=000000007a1ca695
>>>> ceph:  submit_request on 0000000041d5070e for inode 000000007a1ca695
>>>>
>>>> The will be confusing without checking the corresponding code carefully.
>>>>
>>>> Signed-off-by: Xiubo Li <xiubli@redhat.com>
>>>> ---
>>>>    fs/ceph/dir.c        | 2 +-
>>>>    fs/ceph/mds_client.c | 6 +++++-
>>>>    2 files changed, 6 insertions(+), 2 deletions(-)
>>>>
>>>> diff --git a/fs/ceph/dir.c b/fs/ceph/dir.c
>>>> index ffeaff5bf211..245a262ec198 100644
>>>> --- a/fs/ceph/dir.c
>>>> +++ b/fs/ceph/dir.c
>>>> @@ -798,7 +798,7 @@ static struct dentry *ceph_lookup(struct inode *dir, struct dentry *dentry,
>>>>           err = ceph_handle_snapdir(req, dentry, err);
>>>>           dentry = ceph_finish_lookup(req, dentry, err);
>>>>           ceph_mdsc_put_request(req);  /* will dput(dentry) */
>>>> -       dout("lookup result=%p\n", dentry);
>>>> +       dout("lookup result=%d\n", err);
>>>>           return dentry;
>>>>    }
>>>>
>>>> diff --git a/fs/ceph/mds_client.c b/fs/ceph/mds_client.c
>>>> index b6aa357f7c61..e34f159d262b 100644
>>>> --- a/fs/ceph/mds_client.c
>>>> +++ b/fs/ceph/mds_client.c
>>>> @@ -2772,7 +2772,11 @@ int ceph_mdsc_submit_request(struct ceph_mds_client *mdsc, struct inode *dir,
>>>>                   ceph_get_cap_refs(ceph_inode(req->r_old_dentry_dir),
>>>>                                     CEPH_CAP_PIN);
>>>>
>>>> -       dout("submit_request on %p for inode %p\n", req, dir);
>>>> +       if (dir)
>>>> +               dout("submit_request on %p for inode %p\n", req, dir);
>>>> +       else
>>>> +               dout("submit_request on %p\n", req);
>>> Hi Xiubo,
>>>
>>> It's been this way for a couple of years now.  There are a lot more
>>> douts in libceph, ceph and rbd that are sometimes fed NULL pointers.
>>> I don't think replacing them with conditionals is the way forward.
>>>
>>> I honestly don't know what security concern is addressed by hashing
>>> NULL pointers, but that is what we have...  Ultimately, douts are just
>>> for developers, and when you find yourself having to chase individual
>>> pointers, you usually have a large enough piece of log to figure out
>>> what the NULL hash is.
>> Hi Ilya
>>
>> For the ceph_lookup(). The dentry will be NULL(when the directory exists
>> or -ENOENT) or ERR_PTR(-errno) in most cases here, it seems for the
>> rename case it will be the old dentry returned.
>>
>> So today I was trying to debug and get some logs from it, the
>> 000000007a1ca695 really confused me for a long time before I dig into
>> the source code.
> I was reacting to ceph_mdsc_submit_request() hunk.  Feel free to tweak
> ceph_lookup() or refactor it so that err is not threaded through three
> different functions as Jeff suggested.

Hi Ilya

Oh okay. You are right we can figure out what we need via many other 
dout logs.

I just saw some very confusing logs that the "dentry" in cpeh_lookup() 
and the "inode" in _submit_ are all 000000007a1ca695, so I addressed 
them both here.

Thanks,

BRs


> Thanks,
>
>                  Ilya
>

Re: [PATCH] ceph: fix dout logs for null pointers

[Jeff Layton]

On Mon, 2020-02-17 at 23:42 +0800, Xiubo Li wrote:
> On 2020/2/17 23:27, Ilya Dryomov wrote:
> > On Mon, Feb 17, 2020 at 4:02 PM Xiubo Li <xiubli@redhat.com> wrote:
> > > On 2020/2/17 22:52, Ilya Dryomov wrote:
> > > > On Mon, Feb 17, 2020 at 12:28 PM <xiubli@redhat.com> wrote:
> > > > > From: Xiubo Li <xiubli@redhat.com>
> > > > > 
> > > > > For example, if dentry and inode is NULL, the log will be:
> > > > > ceph:  lookup result=000000007a1ca695
> > > > > ceph:  submit_request on 0000000041d5070e for inode 000000007a1ca695
> > > > > 
> > > > > The will be confusing without checking the corresponding code carefully.
> > > > > 
> > > > > Signed-off-by: Xiubo Li <xiubli@redhat.com>
> > > > > ---
> > > > >    fs/ceph/dir.c        | 2 +-
> > > > >    fs/ceph/mds_client.c | 6 +++++-
> > > > >    2 files changed, 6 insertions(+), 2 deletions(-)
> > > > > 
> > > > > diff --git a/fs/ceph/dir.c b/fs/ceph/dir.c
> > > > > index ffeaff5bf211..245a262ec198 100644
> > > > > --- a/fs/ceph/dir.c
> > > > > +++ b/fs/ceph/dir.c
> > > > > @@ -798,7 +798,7 @@ static struct dentry *ceph_lookup(struct inode *dir, struct dentry *dentry,
> > > > >           err = ceph_handle_snapdir(req, dentry, err);
> > > > >           dentry = ceph_finish_lookup(req, dentry, err);
> > > > >           ceph_mdsc_put_request(req);  /* will dput(dentry) */
> > > > > -       dout("lookup result=%p\n", dentry);
> > > > > +       dout("lookup result=%d\n", err);
> > > > >           return dentry;
> > > > >    }
> > > > > 
> > > > > diff --git a/fs/ceph/mds_client.c b/fs/ceph/mds_client.c
> > > > > index b6aa357f7c61..e34f159d262b 100644
> > > > > --- a/fs/ceph/mds_client.c
> > > > > +++ b/fs/ceph/mds_client.c
> > > > > @@ -2772,7 +2772,11 @@ int ceph_mdsc_submit_request(struct ceph_mds_client *mdsc, struct inode *dir,
> > > > >                   ceph_get_cap_refs(ceph_inode(req->r_old_dentry_dir),
> > > > >                                     CEPH_CAP_PIN);
> > > > > 
> > > > > -       dout("submit_request on %p for inode %p\n", req, dir);
> > > > > +       if (dir)
> > > > > +               dout("submit_request on %p for inode %p\n", req, dir);
> > > > > +       else
> > > > > +               dout("submit_request on %p\n", req);
> > > > Hi Xiubo,
> > > > 
> > > > It's been this way for a couple of years now.  There are a lot more
> > > > douts in libceph, ceph and rbd that are sometimes fed NULL pointers.
> > > > I don't think replacing them with conditionals is the way forward.
> > > > 
> > > > I honestly don't know what security concern is addressed by hashing
> > > > NULL pointers, but that is what we have...  Ultimately, douts are just
> > > > for developers, and when you find yourself having to chase individual
> > > > pointers, you usually have a large enough piece of log to figure out
> > > > what the NULL hash is.
> > > Hi Ilya
> > > 
> > > For the ceph_lookup(). The dentry will be NULL(when the directory exists
> > > or -ENOENT) or ERR_PTR(-errno) in most cases here, it seems for the
> > > rename case it will be the old dentry returned.
> > > 
> > > So today I was trying to debug and get some logs from it, the
> > > 000000007a1ca695 really confused me for a long time before I dig into
> > > the source code.
> > I was reacting to ceph_mdsc_submit_request() hunk.  Feel free to tweak
> > ceph_lookup() or refactor it so that err is not threaded through three
> > different functions as Jeff suggested.
> 
> Hi Ilya
> 
> Oh okay. You are right we can figure out what we need via many other 
> dout logs.
> 
> I just saw some very confusing logs that the "dentry" in cpeh_lookup() 
> and the "inode" in _submit_ are all 000000007a1ca695, so I addressed 
> them both here.
> 

Since Ilya objected to this patch, I'll drop it from testing for now.
Please send a v2 that addresses his concerns if you still want this in.

Thanks,
-- 
Jeff Layton <jlayton@kernel.org>

Re: [PATCH] ceph: fix dout logs for null pointers

[Ilya Dryomov]

On Tue, Feb 18, 2020 at 2:51 PM Jeff Layton <jlayton@kernel.org> wrote:
>
> On Mon, 2020-02-17 at 23:42 +0800, Xiubo Li wrote:
> > On 2020/2/17 23:27, Ilya Dryomov wrote:
> > > On Mon, Feb 17, 2020 at 4:02 PM Xiubo Li <xiubli@redhat.com> wrote:
> > > > On 2020/2/17 22:52, Ilya Dryomov wrote:
> > > > > On Mon, Feb 17, 2020 at 12:28 PM <xiubli@redhat.com> wrote:
> > > > > > From: Xiubo Li <xiubli@redhat.com>
> > > > > >
> > > > > > For example, if dentry and inode is NULL, the log will be:
> > > > > > ceph:  lookup result=000000007a1ca695
> > > > > > ceph:  submit_request on 0000000041d5070e for inode 000000007a1ca695
> > > > > >
> > > > > > The will be confusing without checking the corresponding code carefully.
> > > > > >
> > > > > > Signed-off-by: Xiubo Li <xiubli@redhat.com>
> > > > > > ---
> > > > > >    fs/ceph/dir.c        | 2 +-
> > > > > >    fs/ceph/mds_client.c | 6 +++++-
> > > > > >    2 files changed, 6 insertions(+), 2 deletions(-)
> > > > > >
> > > > > > diff --git a/fs/ceph/dir.c b/fs/ceph/dir.c
> > > > > > index ffeaff5bf211..245a262ec198 100644
> > > > > > --- a/fs/ceph/dir.c
> > > > > > +++ b/fs/ceph/dir.c
> > > > > > @@ -798,7 +798,7 @@ static struct dentry *ceph_lookup(struct inode *dir, struct dentry *dentry,
> > > > > >           err = ceph_handle_snapdir(req, dentry, err);
> > > > > >           dentry = ceph_finish_lookup(req, dentry, err);
> > > > > >           ceph_mdsc_put_request(req);  /* will dput(dentry) */
> > > > > > -       dout("lookup result=%p\n", dentry);
> > > > > > +       dout("lookup result=%d\n", err);
> > > > > >           return dentry;
> > > > > >    }
> > > > > >
> > > > > > diff --git a/fs/ceph/mds_client.c b/fs/ceph/mds_client.c
> > > > > > index b6aa357f7c61..e34f159d262b 100644
> > > > > > --- a/fs/ceph/mds_client.c
> > > > > > +++ b/fs/ceph/mds_client.c
> > > > > > @@ -2772,7 +2772,11 @@ int ceph_mdsc_submit_request(struct ceph_mds_client *mdsc, struct inode *dir,
> > > > > >                   ceph_get_cap_refs(ceph_inode(req->r_old_dentry_dir),
> > > > > >                                     CEPH_CAP_PIN);
> > > > > >
> > > > > > -       dout("submit_request on %p for inode %p\n", req, dir);
> > > > > > +       if (dir)
> > > > > > +               dout("submit_request on %p for inode %p\n", req, dir);
> > > > > > +       else
> > > > > > +               dout("submit_request on %p\n", req);
> > > > > Hi Xiubo,
> > > > >
> > > > > It's been this way for a couple of years now.  There are a lot more
> > > > > douts in libceph, ceph and rbd that are sometimes fed NULL pointers.
> > > > > I don't think replacing them with conditionals is the way forward.
> > > > >
> > > > > I honestly don't know what security concern is addressed by hashing
> > > > > NULL pointers, but that is what we have...  Ultimately, douts are just
> > > > > for developers, and when you find yourself having to chase individual
> > > > > pointers, you usually have a large enough piece of log to figure out
> > > > > what the NULL hash is.
> > > > Hi Ilya
> > > >
> > > > For the ceph_lookup(). The dentry will be NULL(when the directory exists
> > > > or -ENOENT) or ERR_PTR(-errno) in most cases here, it seems for the
> > > > rename case it will be the old dentry returned.
> > > >
> > > > So today I was trying to debug and get some logs from it, the
> > > > 000000007a1ca695 really confused me for a long time before I dig into
> > > > the source code.
> > > I was reacting to ceph_mdsc_submit_request() hunk.  Feel free to tweak
> > > ceph_lookup() or refactor it so that err is not threaded through three
> > > different functions as Jeff suggested.
> >
> > Hi Ilya
> >
> > Oh okay. You are right we can figure out what we need via many other
> > dout logs.
> >
> > I just saw some very confusing logs that the "dentry" in cpeh_lookup()
> > and the "inode" in _submit_ are all 000000007a1ca695, so I addressed
> > them both here.
> >
>
> Since Ilya objected to this patch, I'll drop it from testing for now.
> Please send a v2 that addresses his concerns if you still want this in.

I have submitted a patch to fix printk to not obfuscate NULL and
error pointers and haven't heard any objections yet, so hopefully
this issue will become moot soon.

Thanks,

                Ilya

Re: [PATCH] ceph: fix dout logs for null pointers

[Xiubo Li]

On 2020/2/18 22:10, Ilya Dryomov wrote:
> On Tue, Feb 18, 2020 at 2:51 PM Jeff Layton <jlayton@kernel.org> wrote:
>> On Mon, 2020-02-17 at 23:42 +0800, Xiubo Li wrote:
>>> On 2020/2/17 23:27, Ilya Dryomov wrote:
>>>> On Mon, Feb 17, 2020 at 4:02 PM Xiubo Li <xiubli@redhat.com> wrote:
>>>>> On 2020/2/17 22:52, Ilya Dryomov wrote:
>>>>>> On Mon, Feb 17, 2020 at 12:28 PM <xiubli@redhat.com> wrote:
>>>>>>> From: Xiubo Li <xiubli@redhat.com>
>>>>>>>
>>>>>>> For example, if dentry and inode is NULL, the log will be:
>>>>>>> ceph:  lookup result=000000007a1ca695
>>>>>>> ceph:  submit_request on 0000000041d5070e for inode 000000007a1ca695
>>>>>>>
>>>>>>> The will be confusing without checking the corresponding code carefully.
>>>>>>>
>>>>>>> Signed-off-by: Xiubo Li <xiubli@redhat.com>
>>>>>>> ---
>>>>>>>     fs/ceph/dir.c        | 2 +-
>>>>>>>     fs/ceph/mds_client.c | 6 +++++-
>>>>>>>     2 files changed, 6 insertions(+), 2 deletions(-)
>>>>>>>
>>>>>>> diff --git a/fs/ceph/dir.c b/fs/ceph/dir.c
>>>>>>> index ffeaff5bf211..245a262ec198 100644
>>>>>>> --- a/fs/ceph/dir.c
>>>>>>> +++ b/fs/ceph/dir.c
>>>>>>> @@ -798,7 +798,7 @@ static struct dentry *ceph_lookup(struct inode *dir, struct dentry *dentry,
>>>>>>>            err = ceph_handle_snapdir(req, dentry, err);
>>>>>>>            dentry = ceph_finish_lookup(req, dentry, err);
>>>>>>>            ceph_mdsc_put_request(req);  /* will dput(dentry) */
>>>>>>> -       dout("lookup result=%p\n", dentry);
>>>>>>> +       dout("lookup result=%d\n", err);
>>>>>>>            return dentry;
>>>>>>>     }
>>>>>>>
>>>>>>> diff --git a/fs/ceph/mds_client.c b/fs/ceph/mds_client.c
>>>>>>> index b6aa357f7c61..e34f159d262b 100644
>>>>>>> --- a/fs/ceph/mds_client.c
>>>>>>> +++ b/fs/ceph/mds_client.c
>>>>>>> @@ -2772,7 +2772,11 @@ int ceph_mdsc_submit_request(struct ceph_mds_client *mdsc, struct inode *dir,
>>>>>>>                    ceph_get_cap_refs(ceph_inode(req->r_old_dentry_dir),
>>>>>>>                                      CEPH_CAP_PIN);
>>>>>>>
>>>>>>> -       dout("submit_request on %p for inode %p\n", req, dir);
>>>>>>> +       if (dir)
>>>>>>> +               dout("submit_request on %p for inode %p\n", req, dir);
>>>>>>> +       else
>>>>>>> +               dout("submit_request on %p\n", req);
>>>>>> Hi Xiubo,
>>>>>>
>>>>>> It's been this way for a couple of years now.  There are a lot more
>>>>>> douts in libceph, ceph and rbd that are sometimes fed NULL pointers.
>>>>>> I don't think replacing them with conditionals is the way forward.
>>>>>>
>>>>>> I honestly don't know what security concern is addressed by hashing
>>>>>> NULL pointers, but that is what we have...  Ultimately, douts are just
>>>>>> for developers, and when you find yourself having to chase individual
>>>>>> pointers, you usually have a large enough piece of log to figure out
>>>>>> what the NULL hash is.
>>>>> Hi Ilya
>>>>>
>>>>> For the ceph_lookup(). The dentry will be NULL(when the directory exists
>>>>> or -ENOENT) or ERR_PTR(-errno) in most cases here, it seems for the
>>>>> rename case it will be the old dentry returned.
>>>>>
>>>>> So today I was trying to debug and get some logs from it, the
>>>>> 000000007a1ca695 really confused me for a long time before I dig into
>>>>> the source code.
>>>> I was reacting to ceph_mdsc_submit_request() hunk.  Feel free to tweak
>>>> ceph_lookup() or refactor it so that err is not threaded through three
>>>> different functions as Jeff suggested.
>>> Hi Ilya
>>>
>>> Oh okay. You are right we can figure out what we need via many other
>>> dout logs.
>>>
>>> I just saw some very confusing logs that the "dentry" in cpeh_lookup()
>>> and the "inode" in _submit_ are all 000000007a1ca695, so I addressed
>>> them both here.
>>>
>> Since Ilya objected to this patch, I'll drop it from testing for now.
>> Please send a v2 that addresses his concerns if you still want this in.
> I have submitted a patch to fix printk to not obfuscate NULL and
> error pointers and haven't heard any objections yet, so hopefully
> this issue will become moot soon.

Hi Jeff, Ilya

Yeah, this is very cool for me. This will just work like the string 
pointer formating, if it is NULL it then will be formated as 
"null"/"nil" or something instead.

Thanks

BRs


> Thanks,
>
>                  Ilya
>