[PATCH] sysdb_set_entry_attr: dump attributes and values on error

[Sumit Bose]

Hi,

this is a patch I have in my tree for some time for debugging purposes.
Recently I've seen some bug reports with "ldb_modify failed" messages in
the logs and I think this patch might help in those cases.

Additionally I wonder if SSSDBG_MINOR_FAILURE is a suitable debug level
here. In most cases an error here prevents a user or group object to be
written to the cache, so maybe SSSDBG_CRIT_FAILURE is justified here?

bye,
Sumit

[Pavel Reichl]

On 03/09/2015 10:13 AM, Sumit Bose wrote:
> Hi,
>
> this is a patch I have in my tree for some time for debugging purposes.
> Recently I've seen some bug reports with "ldb_modify failed" messages in
> the logs and I think this patch might help in those cases.
>
> Additionally I wonder if SSSDBG_MINOR_FAILURE is a suitable debug level
> here. In most cases an error here prevents a user or group object to be
> written to the cache, so maybe SSSDBG_CRIT_FAILURE is justified here?
>
> bye,
> Sumit
>
> sssd-devel mailing list
> [e-mail]
> https://lists.fedorahosted.org/mailman/listinfo/sssd-devel

Hello Sumit,

when compiling at my environment, I'm seeing this warning:

../src/db/sysdb_ops.c: In function 'sysdb_set_entry_attr':
../src/db/sysdb_ops.c:717:21: warning: format '%u' expects argument of 
type 'unsigned int', but argument 6 has type 'size_t' [-Wformat=]
                      DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%u]: [%s].\n",

Would you consider amending the patch?
-                    DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%u]: [%s].\n",
+                    DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%zu]: [%s].\n",

This seem to remove the warning for me.

Thanks!

[Sumit Bose]

On Mon, Mar 09, 2015 at 11:24:31AM +0100, Pavel Reichl wrote:
> On 03/09/2015 10:13 AM, Sumit Bose wrote:
> > Hi,
> >
> > this is a patch I have in my tree for some time for debugging purposes.
> > Recently I've seen some bug reports with "ldb_modify failed" messages in
> > the logs and I think this patch might help in those cases.
> >
> > Additionally I wonder if SSSDBG_MINOR_FAILURE is a suitable debug level
> > here. In most cases an error here prevents a user or group object to be
> > written to the cache, so maybe SSSDBG_CRIT_FAILURE is justified here?
> >
> > bye,
> > Sumit
> >
> > sssd-devel mailing list
> > [e-mail]
> > https://lists.fedorahosted.org/mailman/listinfo/sssd-devel
>
> Hello Sumit,
>
> when compiling at my environment, I'm seeing this warning:
>
> ../src/db/sysdb_ops.c: In function 'sysdb_set_entry_attr':
> ../src/db/sysdb_ops.c:717:21: warning: format '%u' expects argument of type
> 'unsigned int', but argument 6 has type 'size_t' [-Wformat=]
>                      DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%u]: [%s].\n",
>
> Would you consider amending the patch?
>                DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%u]: [%s].\n",
>                DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%zu]: [%s].\n",

Of course, thank you for catching this, new version attached.

bye,
Sumit
> This seem to remove the warning for me.
>
> Thanks!

[Pavel Reichl]

On 03/09/2015 12:03 PM, Sumit Bose wrote:
> On Mon, Mar 09, 2015 at 11:24:31AM +0100, Pavel Reichl wrote:
> > On 03/09/2015 10:13 AM, Sumit Bose wrote:
> > > Hi,
> > >
> > > this is a patch I have in my tree for some time for debugging purposes.
> > > Recently I've seen some bug reports with "ldb_modify failed" messages in
> > > the logs and I think this patch might help in those cases.
> > >
> > > Additionally I wonder if SSSDBG_MINOR_FAILURE is a suitable debug level
> > > here. In most cases an error here prevents a user or group object to be
> > > written to the cache, so maybe SSSDBG_CRIT_FAILURE is justified here?
> > >
> > > bye,
> > > Sumit
> > >
> > > sssd-devel mailing list
> > > [e-mail]
> > > https://lists.fedorahosted.org/mailman/listinfo/sssd-devel
> >
> > Hello Sumit,
> >
> > when compiling at my environment, I'm seeing this warning:
> >
> > ../src/db/sysdb_ops.c: In function 'sysdb_set_entry_attr':
> > ../src/db/sysdb_ops.c:717:21: warning: format '%u' expects argument of type
> > 'unsigned int', but argument 6 has type 'size_t' [-Wformat=]
> >                       DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%u]: [%s].\n",
> >
> > Would you consider amending the patch?
> >                DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%u]: [%s].\n",
> >                DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%zu]: [%s].\n",
>
> Of course, thank you for catching this, new version attached.
>
> bye,
> Sumit
> > This seem to remove the warning for me.
> >
> > Thanks!
> >
> > sssd-devel mailing list
> > [e-mail]
> > https://lists.fedorahosted.org/mailman/listinfo/sssd-devel

Thanks:

ci: failed on RHEL 7 on test-negcache - I think this is a false positive.
http://sssd-ci.duckdns.org/logs/job/9/05/summary.html

ACK

[Jakub Hrozek]

On Mon, Mar 09, 2015 at 02:08:06PM +0100, Pavel Reichl wrote:
> Thanks:
>
> ci: failed on RHEL 7 on test-negcache - I think this is a false positive.
> http://sssd-ci.duckdns.org/logs/job/9/05/summary.html

yes, that test is know to not be very robust
> ACK

About the log level, what do you think about using IMPORTANT_INFO ?

[Lukas Slebodnik]

On (09/03/15 12:03), Sumit Bose wrote:
> On Mon, Mar 09, 2015 at 11:24:31AM +0100, Pavel Reichl wrote:
> > On 03/09/2015 10:13 AM, Sumit Bose wrote:
> > > Hi,
> > >
> > > this is a patch I have in my tree for some time for debugging purposes.
> > > Recently I've seen some bug reports with "ldb_modify failed" messages in
> > > the logs and I think this patch might help in those cases.
> > >
> > > Additionally I wonder if SSSDBG_MINOR_FAILURE is a suitable debug level
> > > here. In most cases an error here prevents a user or group object to be
> > > written to the cache, so maybe SSSDBG_CRIT_FAILURE is justified here?
> > >
> > > bye,
> > > Sumit
> >
> > Hello Sumit,
> >
> > when compiling at my environment, I'm seeing this warning:
> >
> > ../src/db/sysdb_ops.c: In function 'sysdb_set_entry_attr':
> > ../src/db/sysdb_ops.c:717:21: warning: format '%u' expects argument of type
> > 'unsigned int', but argument 6 has type 'size_t' [-Wformat=]
> >                      DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%u]: [%s].\n",
> >
> > Would you consider amending the patch?
> >                DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%u]: [%s].\n",
> >                DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%zu]: [%s].\n",
>
> Of course, thank you for catching this, new version attached.
>
> bye,
> Sumit
> > This seem to remove the warning for me.
> >
> > Thanks!
> From eaa3bbdea943dd509632e4ccb97c9278bd1208a3 Mon Sep 17 00:00:00 2001
> From: Sumit Bose 
> Date: Wed, 21 Jan 2015 11:05:23 +0100
> Subject: [PATCH] sysdb_set_entry_attr: dump attributes and values on error
>
> src/db/sysdb_ops.c | 11 +++++++++++
> 1 file changed, 11 insertions(+)
>
> diff --git a/src/db/sysdb_ops.c b/src/db/sysdb_ops.c
> index 6085762dcc5585114dd3049dd3a365856cb6b190..5d25d11f0cc10ab3e59420231e8acfa0e58fbf4b 100644
> --- a/src/db/sysdb_ops.c
> +++ b/src/db/sysdb_ops.c
> @@ -671,6 +671,7 @@ int sysdb_set_entry_attr(struct sysdb_ctx *sysdb,
>     struct ldb_message *msg;
>     int i, ret;
>     int lret;
>
> size_t c;
> TALLOC_CTX *tmp_ctx;
>
> tmp_ctx = talloc_new(NULL);
>
> @@ -708,6 +709,16 @@ int sysdb_set_entry_attr(struct sysdb_ctx *sysdb,
>     if (lret != LDB_SUCCESS) {
>         DEBUG(SSSDBG_MINOR_FAILURE,
>               "ldb_modify failed: [%s]\n", ldb_strerror(lret));
>    if (DEBUG_IS_SET(SSSDBG_MINOR_FAILURE)) {
>        for (i = 0; i < msg->num_elements; i++) {
>            DEBUG(SSSDBG_MINOR_FAILURE, "Name: [%s].\n",
>                  msg->elements[i].name);
>            for (c = 0; c < msg->elements[i].num_values; c++) {
>                DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%zu]: [%s].\n",
>                      c, msg->elements[i].values[c].data);
>            }
>        }
>    }

I'm sorry but this patch isn't very useful
I am debugging bug #2576 and it didn't help me with anything
and I really got a message "ldb_modify failed"

It seems to be some issue with ghost attributes which are not present
in stored msg. They are generated by memberof plug-in.

LS

[Sumit Bose]

On Mon, Mar 09, 2015 at 06:36:51PM +0100, Lukas Slebodnik wrote:
> On (09/03/15 12:03), Sumit Bose wrote:
> > On Mon, Mar 09, 2015 at 11:24:31AM +0100, Pavel Reichl wrote:
> > > On 03/09/2015 10:13 AM, Sumit Bose wrote:
> > > > Hi,
> > > >
> > > > this is a patch I have in my tree for some time for debugging purposes.
> > > > Recently I've seen some bug reports with "ldb_modify failed" messages in
> > > > the logs and I think this patch might help in those cases.
> > > >
> > > > Additionally I wonder if SSSDBG_MINOR_FAILURE is a suitable debug level
> > > > here. In most cases an error here prevents a user or group object to be
> > > > written to the cache, so maybe SSSDBG_CRIT_FAILURE is justified here?
> > > >
> > > > bye,
> > > > Sumit
> > >
> > > Hello Sumit,
> > >
> > > when compiling at my environment, I'm seeing this warning:
> > >
> > > ../src/db/sysdb_ops.c: In function 'sysdb_set_entry_attr':
> > > ../src/db/sysdb_ops.c:717:21: warning: format '%u' expects argument of type
> > > 'unsigned int', but argument 6 has type 'size_t' [-Wformat=]
> > >                      DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%u]: [%s].\n",
> > >
> > > Would you consider amending the patch?
> > >                DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%u]: [%s].\n",
> > >                DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%zu]: [%s].\n",
> >
> > Of course, thank you for catching this, new version attached.
> >
> > bye,
> > Sumit
> > > This seem to remove the warning for me.
> > >
> > > Thanks!
> > From eaa3bbdea943dd509632e4ccb97c9278bd1208a3 Mon Sep 17 00:00:00 2001
> > From: Sumit Bose 
> > Date: Wed, 21 Jan 2015 11:05:23 +0100
> > Subject: [PATCH] sysdb_set_entry_attr: dump attributes and values on error
> >
> > src/db/sysdb_ops.c | 11 +++++++++++
> > 1 file changed, 11 insertions(+)
> >
> > diff --git a/src/db/sysdb_ops.c b/src/db/sysdb_ops.c
> > index 6085762dcc5585114dd3049dd3a365856cb6b190..5d25d11f0cc10ab3e59420231e8acfa0e58fbf4b 100644
> > --- a/src/db/sysdb_ops.c
> > +++ b/src/db/sysdb_ops.c
> > @@ -671,6 +671,7 @@ int sysdb_set_entry_attr(struct sysdb_ctx *sysdb,
> >     struct ldb_message *msg;
> >     int i, ret;
> >     int lret;
> >
> > size_t c;
> > TALLOC_CTX *tmp_ctx;
> >
> > tmp_ctx = talloc_new(NULL);
> >
> > @@ -708,6 +709,16 @@ int sysdb_set_entry_attr(struct sysdb_ctx *sysdb,
> >     if (lret != LDB_SUCCESS) {
> >         DEBUG(SSSDBG_MINOR_FAILURE,
> >               "ldb_modify failed: [%s]\n", ldb_strerror(lret));
> >    if (DEBUG_IS_SET(SSSDBG_MINOR_FAILURE)) {
> >        for (i = 0; i < msg->num_elements; i++) {
> >            DEBUG(SSSDBG_MINOR_FAILURE, "Name: [%s].\n",
> >                  msg->elements[i].name);
> >            for (c = 0; c < msg->elements[i].num_values; c++) {
> >                DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%zu]: [%s].\n",
> >                      c, msg->elements[i].values[c].data);
> >            }
> >        }
> >    }
>
> I'm sorry but this patch isn't very useful
> I am debugging bug #2576 and it didn't help me with anything
> and I really got a message "ldb_modify failed"
>
> It seems to be some issue with ghost attributes which are not present
> in stored msg. They are generated by memberof plug-in.

yes, this does not help with 'internal' errors. It would be possible to
print the list only on LDB_ERR_CONSTRAINT_VIOLATION,
LDB_ERR_ATTRIBUTE_OR_VALUE_EXISTS, LDB_ERR_INVALID_ATTRIBUTE_SYNTAX or
any other error code related to the input attributes. But I thought
chances are high to miss an error code and so dump the stuff on all
errors.

bye,
Sumit
> LS
> _______________________________________________
> sssd-devel mailing list
> [e-mail]
> https://lists.fedorahosted.org/mailman/listinfo/sssd-devel

[Lukas Slebodnik]

On (10/03/15 16:30), Sumit Bose wrote:
> On Mon, Mar 09, 2015 at 06:36:51PM +0100, Lukas Slebodnik wrote:
> > On (09/03/15 12:03), Sumit Bose wrote:
> > > On Mon, Mar 09, 2015 at 11:24:31AM +0100, Pavel Reichl wrote:
> > > > On 03/09/2015 10:13 AM, Sumit Bose wrote:
> > > > > Hi,
> > > > >
> > > > > this is a patch I have in my tree for some time for debugging purposes.
> > > > > Recently I've seen some bug reports with "ldb_modify failed" messages in
> > > > > the logs and I think this patch might help in those cases.
> > > > >
> > > > > Additionally I wonder if SSSDBG_MINOR_FAILURE is a suitable debug level
> > > > > here. In most cases an error here prevents a user or group object to be
> > > > > written to the cache, so maybe SSSDBG_CRIT_FAILURE is justified here?
> > > > >
> > > > > bye,
> > > > > Sumit
> > > >
> > > > Hello Sumit,
> > > >
> > > > when compiling at my environment, I'm seeing this warning:
> > > >
> > > > ../src/db/sysdb_ops.c: In function 'sysdb_set_entry_attr':
> > > > ../src/db/sysdb_ops.c:717:21: warning: format '%u' expects argument of type
> > > > 'unsigned int', but argument 6 has type 'size_t' [-Wformat=]
> > > >                      DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%u]: [%s].\n",
> > > >
> > > > Would you consider amending the patch?
> > > >                DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%u]: [%s].\n",
> > > >                DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%zu]: [%s].\n",
> > >
> > > Of course, thank you for catching this, new version attached.
> > >
> > > bye,
> > > Sumit
> > > > This seem to remove the warning for me.
> > > >
> > > > Thanks!
> > > From eaa3bbdea943dd509632e4ccb97c9278bd1208a3 Mon Sep 17 00:00:00 2001
> > > From: Sumit Bose 
> > > Date: Wed, 21 Jan 2015 11:05:23 +0100
> > > Subject: [PATCH] sysdb_set_entry_attr: dump attributes and values on error
> > >
> > > src/db/sysdb_ops.c | 11 +++++++++++
> > > 1 file changed, 11 insertions(+)
> > >
> > > diff --git a/src/db/sysdb_ops.c b/src/db/sysdb_ops.c
> > > index 6085762dcc5585114dd3049dd3a365856cb6b190..5d25d11f0cc10ab3e59420231e8acfa0e58fbf4b 100644
> > > --- a/src/db/sysdb_ops.c
> > > +++ b/src/db/sysdb_ops.c
> > > @@ -671,6 +671,7 @@ int sysdb_set_entry_attr(struct sysdb_ctx *sysdb,
> > >     struct ldb_message *msg;
> > >     int i, ret;
> > >     int lret;
> > >
> > > size_t c;
> > > TALLOC_CTX *tmp_ctx;
> > >
> > > tmp_ctx = talloc_new(NULL);
> > >
> > > @@ -708,6 +709,16 @@ int sysdb_set_entry_attr(struct sysdb_ctx *sysdb,
> > >     if (lret != LDB_SUCCESS) {
> > >         DEBUG(SSSDBG_MINOR_FAILURE,
> > >               "ldb_modify failed: [%s]\n", ldb_strerror(lret));
> > >    if (DEBUG_IS_SET(SSSDBG_MINOR_FAILURE)) {
> > >        for (i = 0; i < msg->num_elements; i++) {
> > >            DEBUG(SSSDBG_MINOR_FAILURE, "Name: [%s].\n",
> > >                  msg->elements[i].name);
> > >            for (c = 0; c < msg->elements[i].num_values; c++) {
> > >                DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%zu]: [%s].\n",
> > >                      c, msg->elements[i].values[c].data);
> > >            }
> > >        }
> > >    }
> >
> > I'm sorry but this patch isn't very useful
> > I am debugging bug #2576 and it didn't help me with anything
> > and I really got a message "ldb_modify failed"
> >
> > It seems to be some issue with ghost attributes which are not present
> > in stored msg. They are generated by memberof plug-in.
>
> yes, this does not help with 'internal' errors. It would be possible to
> print the list only on LDB_ERR_CONSTRAINT_VIOLATION,
> LDB_ERR_ATTRIBUTE_OR_VALUE_EXISTS, LDB_ERR_INVALID_ATTRIBUTE_SYNTAX or
> any other error code related to the input attributes. But I thought
> chances are high to miss an error code and so dump the stuff on all
> errors.

As I already mention it will not help.
In my case, LDB_ERR_CONSTRAINT_VIOLATION was returned.
The error from ldb said:
attribute 'ghost': attribute on 'name=groupA,cn=groups,cn=LDAP,cn=sysdb'
specified, but with 0 values (illegal)

But with your patch I could see that ghost attribute was present in msg.

Long story short. It was bug in memberof plugin. I will send patch for review,
but I want to find simpler reproducer (& write unit test)

We already use function ldb_errstring on some places.
    /**
      return extended error information from the last call
    */
    const char *ldb_errstring(struct ldb_context *ldb);

Attached is a patch with use ldb_errstring in error handling branch
after calling ldb_modify. IMHO it is more useful than dump of msg.

LS

[Sumit Bose]

On Tue, Mar 10, 2015 at 06:47:44PM +0100, Lukas Slebodnik wrote:
> On (10/03/15 16:30), Sumit Bose wrote:
> > On Mon, Mar 09, 2015 at 06:36:51PM +0100, Lukas Slebodnik wrote:
> > > On (09/03/15 12:03), Sumit Bose wrote:
> > > > On Mon, Mar 09, 2015 at 11:24:31AM +0100, Pavel Reichl wrote:
> > > > > On 03/09/2015 10:13 AM, Sumit Bose wrote:
> > > > > > Hi,
> > > > > >
> > > > > > this is a patch I have in my tree for some time for debugging purposes.
> > > > > > Recently I've seen some bug reports with "ldb_modify failed" messages in
> > > > > > the logs and I think this patch might help in those cases.
> > > > > >
> > > > > > Additionally I wonder if SSSDBG_MINOR_FAILURE is a suitable debug level
> > > > > > here. In most cases an error here prevents a user or group object to be
> > > > > > written to the cache, so maybe SSSDBG_CRIT_FAILURE is justified here?
> > > > > >
> > > > > > bye,
> > > > > > Sumit
> > > > >
> > > > > Hello Sumit,
> > > > >
> > > > > when compiling at my environment, I'm seeing this warning:
> > > > >
> > > > > ../src/db/sysdb_ops.c: In function 'sysdb_set_entry_attr':
> > > > > ../src/db/sysdb_ops.c:717:21: warning: format '%u' expects argument of type
> > > > > 'unsigned int', but argument 6 has type 'size_t' [-Wformat=]
> > > > >                      DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%u]: [%s].\n",
> > > > >
> > > > > Would you consider amending the patch?
> > > > >                DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%u]: [%s].\n",
> > > > >                DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%zu]: [%s].\n",
> > > >
> > > > Of course, thank you for catching this, new version attached.
> > > >
> > > > bye,
> > > > Sumit
> > > > > This seem to remove the warning for me.
> > > > >
> > > > > Thanks!
> > > > From eaa3bbdea943dd509632e4ccb97c9278bd1208a3 Mon Sep 17 00:00:00 2001
> > > > From: Sumit Bose 
> > > > Date: Wed, 21 Jan 2015 11:05:23 +0100
> > > > Subject: [PATCH] sysdb_set_entry_attr: dump attributes and values on error
> > > >
> > > > src/db/sysdb_ops.c | 11 +++++++++++
> > > > 1 file changed, 11 insertions(+)
> > > >
> > > > diff --git a/src/db/sysdb_ops.c b/src/db/sysdb_ops.c
> > > > index 6085762dcc5585114dd3049dd3a365856cb6b190..5d25d11f0cc10ab3e59420231e8acfa0e58fbf4b 100644
> > > > --- a/src/db/sysdb_ops.c
> > > > +++ b/src/db/sysdb_ops.c
> > > > @@ -671,6 +671,7 @@ int sysdb_set_entry_attr(struct sysdb_ctx *sysdb,
> > > >     struct ldb_message *msg;
> > > >     int i, ret;
> > > >     int lret;
> > > >
> > > > size_t c;
> > > > TALLOC_CTX *tmp_ctx;
> > > >
> > > > tmp_ctx = talloc_new(NULL);
> > > >
> > > > @@ -708,6 +709,16 @@ int sysdb_set_entry_attr(struct sysdb_ctx *sysdb,
> > > >     if (lret != LDB_SUCCESS) {
> > > >         DEBUG(SSSDBG_MINOR_FAILURE,
> > > >               "ldb_modify failed: [%s]\n", ldb_strerror(lret));
> > > >    if (DEBUG_IS_SET(SSSDBG_MINOR_FAILURE)) {
> > > >        for (i = 0; i < msg->num_elements; i++) {
> > > >            DEBUG(SSSDBG_MINOR_FAILURE, "Name: [%s].\n",
> > > >                  msg->elements[i].name);
> > > >            for (c = 0; c < msg->elements[i].num_values; c++) {
> > > >                DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%zu]: [%s].\n",
> > > >                      c, msg->elements[i].values[c].data);
> > > >            }
> > > >        }
> > > >    }
> > >
> > > I'm sorry but this patch isn't very useful
> > > I am debugging bug #2576 and it didn't help me with anything
> > > and I really got a message "ldb_modify failed"
> > >
> > > It seems to be some issue with ghost attributes which are not present
> > > in stored msg. They are generated by memberof plug-in.
> >
> > yes, this does not help with 'internal' errors. It would be possible to
> > print the list only on LDB_ERR_CONSTRAINT_VIOLATION,
> > LDB_ERR_ATTRIBUTE_OR_VALUE_EXISTS, LDB_ERR_INVALID_ATTRIBUTE_SYNTAX or
> > any other error code related to the input attributes. But I thought
> > chances are high to miss an error code and so dump the stuff on all
> > errors.
>
> As I already mention it will not help.
> In my case, LDB_ERR_CONSTRAINT_VIOLATION was returned.
> The error from ldb said:
> attribute 'ghost': attribute on 'name=groupA,cn=groups,cn=LDAP,cn=sysdb'
> specified, but with 0 values (illegal)

ah, now I see your point, I didn't realize that libldb returns such
useful error messages.
> But with your patch I could see that ghost attribute was present in msg.

But I would assume that the value was empty, or was the value remove
during memberOf processing?
> Long story short. It was bug in memberof plugin. I will send patch for review,
> but I want to find simpler reproducer (& write unit test)
>
> We already use function ldb_errstring on some places.
>     /**
>       return extended error information from the last call
>     */
>     const char *ldb_errstring(struct ldb_context *ldb);
>
> Attached is a patch with use ldb_errstring in error handling branch
> after calling ldb_modify. IMHO it is more useful than dump of msg.

ok, ACK to your patch,
http://sssd-ci.duckdns.org/logs/job/9/32/summary.html .

bye,
Sumit
> LS
> From 2808cff66f4984bad12def6ee84ae6a61a1dc35d Mon Sep 17 00:00:00 2001
> From: Lukas Slebodnik 
> Date: Tue, 10 Mar 2015 16:35:03 +0100
> Subject: [PATCH] Log reason in debug message why ldb_modify failed
>
> src/confdb/confdb.c     |  6 +++++-
>  src/db/sysdb.c          |  5 +++++
>  src/db/sysdb_gpo.c      |  6 ++++--
>  src/db/sysdb_idmap.c    |  4 ++--
>  src/db/sysdb_ops.c      | 28 +++++++++++++++++++++++++++-
>  src/db/sysdb_services.c | 10 ++++++++++
>  src/db/sysdb_sudo.c     |  5 +++++
>  src/db/sysdb_views.c    | 14 ++++++++++----
>  8 files changed, 68 insertions(+), 10 deletions(-)
>
> diff --git a/src/confdb/confdb.c b/src/confdb/confdb.c
> index f94de308ec8245b33b4a69af16dd99d17db8db9a..dd93410cfcac3040d5a72329929f99f43fc592f1 100644
> --- a/src/confdb/confdb.c
> +++ b/src/confdb/confdb.c
> @@ -200,6 +200,9 @@ int confdb_add_param(struct confdb_ctx *cdb,
>      ret = ldb_modify(cdb->ldb, msg);
>      if (ret != LDB_SUCCESS) {
>        DEBUG(SSSDBG_MINOR_FAILURE,
>              "ldb_modify failed: [%s](%d)[%s]\n",
>              ldb_strerror(ret), ret, ldb_errstring(cdb->ldb));
>        ret = EIO;
>        goto done;
>    }
>
> @@ -348,7 +351,8 @@ int confdb_set_string(struct confdb_ctx *cdb,
>      lret = ldb_modify(cdb->ldb, msg);
>      if (lret != LDB_SUCCESS) {
>          DEBUG(SSSDBG_MINOR_FAILURE,
>          "ldb_modify failed: [%s]\n", ldb_strerror(lret));
>          "ldb_modify failed: [%s](%d)[%s]\n",
>          ldb_strerror(lret), lret, ldb_errstring(cdb->ldb));
>    ret = EIO;
>    goto done;
> }
>
> diff --git a/src/db/sysdb.c b/src/db/sysdb.c
> index 61a2240016b5cb77e6fbbc3286fd1a194c5a0b48..770c0f1932a45d680d30cd9639a73cd476c3265e 100644
> --- a/src/db/sysdb.c
> +++ b/src/db/sysdb.c
> @@ -1621,6 +1621,11 @@ errno_t sysdb_set_bool(struct sysdb_ctx *sysdb,
>          lret = ldb_add(sysdb->ldb, msg);
>      }
> if (lret != LDB_SUCCESS) {
>    DEBUG(SSSDBG_OP_FAILURE,
>          "ldb operation failed: [%s](%d)[%s]\n",
>          ldb_strerror(lret), lret, ldb_errstring(sysdb->ldb));
> }
> ret = sysdb_error_to_errno(lret);
>
> done:
> diff --git a/src/db/sysdb_gpo.c b/src/db/sysdb_gpo.c
> index b43565cbfd5a71f855d10f63b3bfbc790655549d..e5af91bd8efd1f953326f8069c5c620ca3692017 100644
> --- a/src/db/sysdb_gpo.c
> +++ b/src/db/sysdb_gpo.c
> @@ -208,7 +208,8 @@ sysdb_gpo_store_gpo(struct sss_domain_info *domain,
>          lret = ldb_modify(domain->sysdb->ldb, update_msg);
>          if (lret != LDB_SUCCESS) {
>              DEBUG(SSSDBG_MINOR_FAILURE,
>              "Failed to modify GPO: [%s]\n", ldb_strerror(lret));
>              "Failed to modify GPO: [%s](%d)[%s]\n",
>              ldb_strerror(lret), lret, ldb_errstring(domain->sysdb->ldb));
>        ret = sysdb_error_to_errno(lret);
>        goto done;
>    }
>
> @@ -500,7 +501,8 @@ sysdb_gpo_store_gpo_result_setting(struct sss_domain_info *domain,
>          lret = ldb_modify(domain->sysdb->ldb, update_msg);
>          if (lret != LDB_SUCCESS) {
>              DEBUG(SSSDBG_MINOR_FAILURE,
>              "Failed to modify GPO Result: [%s]\n", ldb_strerror(lret));
>              "Failed to modify GPO Result: [%s](%d)[%s]\n",
>              ldb_strerror(lret), lret, ldb_errstring(domain->sysdb->ldb));
>        ret = sysdb_error_to_errno(lret);
>        goto done;
>    }
>
> diff --git a/src/db/sysdb_idmap.c b/src/db/sysdb_idmap.c
> index 2c3634d1cc86818007700a43dc6b919c9bf7030e..2aa00ef83f182a77b0e9b94ba8a80ef71af6518c 100644
> --- a/src/db/sysdb_idmap.c
> +++ b/src/db/sysdb_idmap.c
> @@ -247,8 +247,8 @@ sysdb_idmap_store_mapping(struct sss_domain_info *domain,
>          lret = ldb_modify(domain->sysdb->ldb, update_msg);
>          if (lret != LDB_SUCCESS) {
>              DEBUG(SSSDBG_MINOR_FAILURE,
>              "Failed to update mapping: [%s]\n",
>               ldb_strerror(lret));
>              "Failed to update mapping: [%s](%d)[%s]\n",
>              ldb_strerror(lret), lret, ldb_errstring(domain->sysdb->ldb));
>        ret = sysdb_error_to_errno(lret);
>        goto done;
>    }
>
> diff --git a/src/db/sysdb_ops.c b/src/db/sysdb_ops.c
> index 6085762dcc5585114dd3049dd3a365856cb6b190..06d24f220afc28b39f3856f3f0170818e11d9cf9 100644
> --- a/src/db/sysdb_ops.c
> +++ b/src/db/sysdb_ops.c
> @@ -707,7 +707,8 @@ int sysdb_set_entry_attr(struct sysdb_ctx *sysdb,
>      lret = ldb_modify(sysdb->ldb, msg);
>      if (lret != LDB_SUCCESS) {
>          DEBUG(SSSDBG_MINOR_FAILURE,
>          "ldb_modify failed: [%s]\n", ldb_strerror(lret));
>          "ldb_modify failed: [%s](%d)[%s]\n",
>          ldb_strerror(lret), lret, ldb_errstring(sysdb->ldb));
>
> }
>
> ret = sysdb_error_to_errno(lret);
>
> @@ -969,6 +970,11 @@ int sysdb_get_new_id(struct sss_domain_info *domain,
>      }
>  ret = ldb_modify(domain->sysdb->ldb, msg);
>
> if (ret != LDB_SUCCESS) {
>    DEBUG(SSSDBG_MINOR_FAILURE,
>          "ldb_modify failed: [%s](%d)[%s]\n",
>          ldb_strerror(ret), ret, ldb_errstring(domain->sysdb->ldb));
>
> }
> ret = sysdb_error_to_errno(ret);
>
> *_id = new_id;
>
> @@ -1139,6 +1145,12 @@ sysdb_remove_ghost_from_group(struct sss_domain_info *dom,
>  ret = sss_ldb_modify_permissive(dom->sysdb->ldb, msg);
> if (ret != LDB_SUCCESS) {
>    DEBUG(SSSDBG_MINOR_FAILURE,
>          "sss_ldb_modify_permissive failed: [%s](%d)[%s]\n",
>          ldb_strerror(ret), ret, ldb_errstring(dom->sysdb->ldb));
> }
> ret = sysdb_error_to_errno(ret);
>    if (ret != EOK) {
>        goto done;
>
> @@ -1706,6 +1718,11 @@ int sysdb_mod_group_member(struct sss_domain_info *domain,
>      }
>  ret = ldb_modify(domain->sysdb->ldb, msg);
> if (ret != LDB_SUCCESS) {
>    DEBUG(SSSDBG_MINOR_FAILURE,
>          "ldb_modify failed: [%s](%d)[%s]\n",
>          ldb_strerror(ret), ret, ldb_errstring(domain->sysdb->ldb));
> }
> ret = sysdb_error_to_errno(ret);
>
> fail:
> @@ -2750,6 +2767,12 @@ int sysdb_delete_user(struct sss_domain_info *domain,
>              if (ret) goto fail;
>          ret = ldb_modify(domain->sysdb->ldb, msg);
>        if (ret != LDB_SUCCESS) {
>            DEBUG(SSSDBG_MINOR_FAILURE,
>                  "ldb_modify failed: [%s](%d)[%s]\n",
>                  ldb_strerror(ret), ret,
>                  ldb_errstring(domain->sysdb->ldb));
>        }
>        ret = sysdb_error_to_errno(ret);
>        if (ret != EOK) {
>            goto fail;
>
> @@ -3479,6 +3502,9 @@ errno_t sysdb_remove_attrs(struct sss_domain_info *domain,
>           */
>          lret = ldb_modify(domain->sysdb->ldb, msg);
>          if (lret != LDB_SUCCESS && lret != LDB_ERR_NO_SUCH_ATTRIBUTE) {
>        DEBUG(SSSDBG_MINOR_FAILURE,
>              "ldb_modify failed: [%s](%d)[%s]\n",
>              ldb_strerror(lret), lret, ldb_errstring(domain->sysdb->ldb));
>        ret = sysdb_error_to_errno(lret);
>        goto done;
>    }
>
> diff --git a/src/db/sysdb_services.c b/src/db/sysdb_services.c
> index 5f2315e72735dd4ccc1ecf7962d9cd54b38e4279..37f7ec5ff7e36605acd3b259c1622f1b1086a388 100644
> --- a/src/db/sysdb_services.c
> +++ b/src/db/sysdb_services.c
> @@ -590,6 +590,11 @@ sysdb_svc_update(struct sysdb_ctx *sysdb,
>      }
>  lret = ldb_modify(sysdb->ldb, msg);
> if (lret != LDB_SUCCESS) {
>    DEBUG(SSSDBG_MINOR_FAILURE,
>          "ldb_modify failed: [%s](%d)[%s]\n",
>          ldb_strerror(lret), lret, ldb_errstring(sysdb->ldb));
> }
> ret = sysdb_error_to_errno(lret);
>
> done:
> @@ -623,6 +628,11 @@ sysdb_svc_remove_alias(struct sysdb_ctx *sysdb,
>      if (ret != EOK) goto done;
>  lret = ldb_modify(sysdb->ldb, msg);
> if (lret != LDB_SUCCESS) {
>    DEBUG(SSSDBG_MINOR_FAILURE,
>          "ldb_modify failed: [%s](%d)[%s]\n",
>          ldb_strerror(lret), lret, ldb_errstring(sysdb->ldb));
> }
> ret = sysdb_error_to_errno(lret);
>
> done:
> diff --git a/src/db/sysdb_sudo.c b/src/db/sysdb_sudo.c
> index 261ed82d672cd95f0c0f429a177dae39d3b9c204..54f726ffff907dd2531f5577cf87c84848509d00 100644
> --- a/src/db/sysdb_sudo.c
> +++ b/src/db/sysdb_sudo.c
> @@ -521,6 +521,11 @@ static errno_t sysdb_sudo_set_refresh_time(struct sss_domain_info *domain,
>          lret = ldb_add(domain->sysdb->ldb, msg);
>      }
> if (lret != LDB_SUCCESS) {
>    DEBUG(SSSDBG_MINOR_FAILURE,
>          "ldb operation failed: [%s](%d)[%s]\n",
>          ldb_strerror(lret), lret, ldb_errstring(domain->sysdb->ldb));
> }
> ret = sysdb_error_to_errno(lret);
>
> done:
> diff --git a/src/db/sysdb_views.c b/src/db/sysdb_views.c
> index 717edf20a447003568060cf4d32bf8d47bd93e63..431d3345418ad05f12b025a1c1733c13a89c490a 100644
> --- a/src/db/sysdb_views.c
> +++ b/src/db/sysdb_views.c
> @@ -165,8 +165,10 @@ errno_t sysdb_update_view_name(struct sysdb_ctx *sysdb,
>          ret = ldb_add(sysdb->ldb, msg);
>      }
>      if (ret != LDB_SUCCESS) {
>    DEBUG(SSSDBG_FATAL_FAILURE, "Failed to %s view container",
>                                view_container_exists ? "modify" : "add");
>    DEBUG(SSSDBG_FATAL_FAILURE,
>          "Failed to %s view container [%s](%d)[%s]\n",
>          view_container_exists ? "modify" : "add",
>          ldb_strerror(ret), ret, ldb_errstring(sysdb->ldb));
>    ret = sysdb_error_to_errno(ret);
>    goto done;
> }
>
> @@ -282,7 +284,9 @@ errno_t sysdb_invalidate_overrides(struct sysdb_ctx *sysdb)
>      ret = ldb_modify(sysdb->ldb, msg);
>      if (ret != LDB_SUCCESS && ret != LDB_ERR_NO_SUCH_ATTRIBUTE) {
>        DEBUG(SSSDBG_OP_FAILURE, "ldb_modify failed.\n");
>        DEBUG(SSSDBG_OP_FAILURE,
>              "ldb_modify failed: [%s](%d)[%s]\n",
>              ldb_strerror(ret), ret, ldb_errstring(sysdb->ldb));
>        ret = sysdb_error_to_errno(ret);
>        goto done;
>    }
>
> @@ -303,7 +307,9 @@ errno_t sysdb_invalidate_overrides(struct sysdb_ctx *sysdb)
>      ret = ldb_modify(sysdb->ldb, msg);
>      if (ret != LDB_SUCCESS && ret != LDB_ERR_NO_SUCH_ATTRIBUTE) {
>        DEBUG(SSSDBG_OP_FAILURE, "ldb_modify failed.\n");
>        DEBUG(SSSDBG_OP_FAILURE,
>              "ldb_modify failed: [%s](%d)[%s]\n",
>              ldb_strerror(ret), ret, ldb_errstring(sysdb->ldb));
>        ret = sysdb_error_to_errno(ret);
>        goto done;
>    }
>
> -- 
> 2.3.1
> sssd-devel mailing list
> [e-mail]
> https://lists.fedorahosted.org/mailman/listinfo/sssd-devel

[Lukas Slebodnik]

On (11/03/15 08:31), Sumit Bose wrote:
> On Tue, Mar 10, 2015 at 06:47:44PM +0100, Lukas Slebodnik wrote:
> > On (10/03/15 16:30), Sumit Bose wrote:
> > > On Mon, Mar 09, 2015 at 06:36:51PM +0100, Lukas Slebodnik wrote:
> > > > On (09/03/15 12:03), Sumit Bose wrote:
> > > > > On Mon, Mar 09, 2015 at 11:24:31AM +0100, Pavel Reichl wrote:
> > > > > > On 03/09/2015 10:13 AM, Sumit Bose wrote:
> > > > > > >Hi,
> > > > > > >
> > > > > > >this is a patch I have in my tree for some time for debugging purposes.
> > > > > > >Recently I've seen some bug reports with "ldb_modify failed" messages in
> > > > > > >the logs and I think this patch might help in those cases.
> > > > > > >
> > > > > > >Additionally I wonder if SSSDBG_MINOR_FAILURE is a suitable debug level
> > > > > > >here. In most cases an error here prevents a user or group object to be
> > > > > > >written to the cache, so maybe SSSDBG_CRIT_FAILURE is justified here?
> > > > > > >
> > > > > > >bye,
> > > > > > >Sumit
> > > > > > >
> > > > > > >
> > > > > > Hello Sumit,
> > > > > >
> > > > > > when compiling at my environment, I'm seeing this warning:
> > > > > >
> > > > > > ../src/db/sysdb_ops.c: In function 'sysdb_set_entry_attr':
> > > > > > ../src/db/sysdb_ops.c:717:21: warning: format '%u' expects argument of type
> > > > > > 'unsigned int', but argument 6 has type 'size_t' [-Wformat=]
> > > > > >                      DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%u]: [%s].\n",
> > > > > >
> > > > > > Would you consider amending the patch?
> > > > > >                DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%u]: [%s].\n",
> > > > > >                DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%zu]: [%s].\n",
> > > > >
> > > > > Of course, thank you for catching this, new version attached.
> > > > >
> > > > > bye,
> > > > > Sumit
> > > > > > This seem to remove the warning for me.
> > > > > >
> > > > > > Thanks!
> > > > > From eaa3bbdea943dd509632e4ccb97c9278bd1208a3 Mon Sep 17 00:00:00 2001
> > > > > From: Sumit Bose 
> > > > > Date: Wed, 21 Jan 2015 11:05:23 +0100
> > > > > Subject: [PATCH] sysdb_set_entry_attr: dump attributes and values on error
> > > > >
> > > > > src/db/sysdb_ops.c | 11 +++++++++++
> > > > > 1 file changed, 11 insertions(+)
> > > > >
> > > > > diff --git a/src/db/sysdb_ops.c b/src/db/sysdb_ops.c
> > > > > index 6085762dcc5585114dd3049dd3a365856cb6b190..5d25d11f0cc10ab3e59420231e8acfa0e58fbf4b 100644
> > > > > --- a/src/db/sysdb_ops.c
> > > > > +++ b/src/db/sysdb_ops.c
> > > > > @@ -671,6 +671,7 @@ int sysdb_set_entry_attr(struct sysdb_ctx *sysdb,
> > > > >     struct ldb_message *msg;
> > > > >     int i, ret;
> > > > >     int lret;
> > > > >
> > > > > size_t c;
> > > > > TALLOC_CTX *tmp_ctx;
> > > > >
> > > > > tmp_ctx = talloc_new(NULL);
> > > > >
> > > > > @@ -708,6 +709,16 @@ int sysdb_set_entry_attr(struct sysdb_ctx *sysdb,
> > > > >     if (lret != LDB_SUCCESS) {
> > > > >         DEBUG(SSSDBG_MINOR_FAILURE,
> > > > >               "ldb_modify failed: [%s]\n", ldb_strerror(lret));
> > > > >    if (DEBUG_IS_SET(SSSDBG_MINOR_FAILURE)) {
> > > > >        for (i = 0; i < msg->num_elements; i++) {
> > > > >            DEBUG(SSSDBG_MINOR_FAILURE, "Name: [%s].\n",
> > > > >                  msg->elements[i].name);
> > > > >            for (c = 0; c < msg->elements[i].num_values; c++) {
> > > > >                DEBUG(SSSDBG_MINOR_FAILURE, "   Value[%zu]: [%s].\n",
> > > > >                      c, msg->elements[i].values[c].data);
> > > > >            }
> > > > >        }
> > > > >    }
> > > >
> > > > I'm sorry but this patch isn't very useful
> > > > I am debugging bug #2576 and it didn't help me with anything
> > > > and I really got a message "ldb_modify failed"
> > > >
> > > > It seems to be some issue with ghost attributes which are not present
> > > > in stored msg. They are generated by memberof plug-in.
> > >
> > > yes, this does not help with 'internal' errors. It would be possible to
> > > print the list only on LDB_ERR_CONSTRAINT_VIOLATION,
> > > LDB_ERR_ATTRIBUTE_OR_VALUE_EXISTS, LDB_ERR_INVALID_ATTRIBUTE_SYNTAX or
> > > any other error code related to the input attributes. But I thought
> > > chances are high to miss an error code and so dump the stuff on all
> > > errors.
> >
> > As I already mention it will not help.
> > In my case, LDB_ERR_CONSTRAINT_VIOLATION was returned.
> > The error from ldb said:
> > attribute 'ghost': attribute on 'name=groupA,cn=groups,cn=LDAP,cn=sysdb'
> > specified, but with 0 values (illegal)
>
> ah, now I see your point, I didn't realize that libldb returns such
> useful error messages.

You didn't know but you have already used it in sysdb_views :-)

src/db/sysdb_views.c:585:                  ldb_strerror(ret), ret, ldb_errstring(domain->sysdb->ldb));
src/db/sysdb_views.c:619:                  ldb_strerror(ret), ret, ldb_errstring(domain->sysdb->ldb));
> > But with your patch I could see that ghost attribute was present in msg.
>
> But I would assume that the value was empty, or was the value remove
> during memberOf processing?

Yes, memberof plug-in remove that attribute.

LS

[Jakub Hrozek]

On Wed, Mar 11, 2015 at 08:31:28AM +0100, Sumit Bose wrote:
> ok, ACK to your patch,
> http://sssd-ci.duckdns.org/logs/job/9/32/summary.html .
>
> bye,
> Sumit

* master: 04d138472cc086fb7961f0d378852b09961b1a33
* sssd-1-12: 182675e355aa1013f847d47d21a251250962e61f