That patch looks very wrong to me. The database should get created in sqlite_prepare_dbh.

Is nfsdcltrack actually not working here, or is the problem just the error messages themselves? IIRC, that error message is _normal_ on an upgrade and should go away on the second reboot (once the table is created).

In any case, if the problem is just the messages themselves, then I'd suggest we just change those to be logged at D_GENERAL instead of L_ERROR. We do catch an error there, but it's done in order to query for the version. We know how to handle it if it doesn't work.

Created attachment 1272706 [details]
patch: silence some expected errors

This would probably fix the warning messages if that's the issue.

(In reply to Jeff Layton from comment #8)
> That patch looks very wrong to me. The database should get created in
> sqlite_prepare_dbh.

The patches I uploaded are only for observing issue but not to tweak. 
Let me try to explain my view in a more common way, this time I just insert 2 lines:


        if (ret != SQLITE_OK) {
                xlog(L_ERROR, "Unable to prepare select statement: %s",
                        sqlite3_errmsg(dbh));
+               xlog(L_ERROR, "Exit now");
+               exit(1);
                ret = 0;
                goto out;
        }

The nfsdcltrack will exit after target log, then I just apply it to test:

[root@- x86_64]# rm -rf /var/lib/nfs/nfsdcltrack/main.sqlite 
[root@- x86_64]# nfsdcltrack init
[root@- x86_64]# echo $?
1

[root@- x86_64]# cat /var/log/messages |grep nfsdcltrack
Apr 19 22:17:32 localhost nfsdcltrack[51679]: Unable to prepare select statement: no such table: parameters
Apr 19 22:17:32 localhost nfsdcltrack[51679]: Exit now

[root@- x86_64]# stat /var/lib/nfs/nfsdcltrack/main.sqlite 
  File: ‘/var/lib/nfs/nfsdcltrack/main.sqlite’
  Size: 0         	Blocks: 0          IO Block: 4096   regular empty file

So my real doubt is why it try to run query on a empty file..Maybe it is better to avoid the confusing step or fix the warning level as comment 10 if it is a necessary order.

(In reply to ChunYu Wang from comment #11)

> So my real doubt is why it try to run query on a empty file..Maybe it is
> better to avoid the confusing step or fix the warning level as comment 10 if
> it is a necessary order.

It's trying to run a query on an empty file because the program is not aware that it's empty at the time that it was being opened. After the database has been opened, we need to determine what the schema version is. We do that by querying the parameters table.

One possible outcome there is that the parameters table does not exist yet. In that case, the query will fail like this (and log the message), but that's OK, we'll just go and try to set up the tables in the database if that happens.

I think silencing the warnings is an appropriate fix here, but if you have other concerns then let me know and we can try to address them too.

In fact, if you have the ability to test the patch in comment #10, then that would be helpful. If it fixes the issue, I'll go ahead and send that upstream and mark it with Tested-by credit for you.

(In reply to Jeff Layton from comment #12)

> I think silencing the warnings is an appropriate fix here

Thanks for your explanation! Switching warn level from L_ERROR to D_GENERAL is also a good fix to me.

(In reply to Jeff Layton from comment #13)

Adding another rule and style for rsyslogd to help:

:programname,contains,"nfsdcltrack" /var/log/nfsdcltrack.log

$template TraditionalFormatWithPRI,"%pri-text%: %timegenerated% %HOSTNAME% %syslogtag%%msg:::drop-last-lf%\n"

This issue can be resolved by this patch:

[root@- etc]# rm -rf /var/lib/nfs/nfsdcltrack/main.sqlite
[root@- etc]# nfsdcltrack init
[root@- etc]# cat /var/log/nfsdcltrack.log 
daemon.err: Apr 20 21:06:04 - nfsdcltrack[31805]:Unable to prepare select statement: no such table: parameters
daemon.err: Apr 20 21:06:04 - nfsdcltrack[31805]:Unable to prepare select statement: no such table: parameters
[root@- etc]# rpm -q nfs-utils
nfs-utils-1.3.0-0.40.el7.x86_64

- Update to include this patch in comment 10 -

[root@- etc]# rm -rf /var/log/nfsdcltrack.log
[root@- etc]# rm -rf /var/lib/nfs/nfsdcltrack/main.sqlite
[root@- etc]# nfsdcltrack init
[root@- etc]# cat /var/log/messages 
[root@- etc]# cat /var/log/nfsdcltrack.log
cat: /var/log/nfsdcltrack.log: No such file or directory
[root@- etc]# rpm -q nfs-utils
nfs-utils-1.3.0-0.40.bz1443176.el7.x86_64


This patch is effective, thanks for understanding and the quick fix!

commit 06bbb4ee6f5186e8e83d50767ad5b3b41968e5a6
Author: Jeff Layton <jlayton>
Date:   Wed Apr 26 12:13:50 2017 -0400

    nfsdcltrack: silence some expected errors

Test results with two nfs-utils versions: 

[04:29:53 root@ ~~]# >/var/log/messages
[04:29:53 root@ ~~]# rm -rf /var/lib/nfs/nfsdcltrack/main.sqlite
[04:29:53 root@ ~~]# nfsdcltrack init

- nfs-utils-1.3.0-0.40.el7:
[04:29:53 root@ ~~]# cat /var/log/messages | grep 'nfsdcltrack.*Unable'
Apr 28 04:29:53 localhost nfsdcltrack[14827]: Unable to prepare select statement: no such table: parameters
Apr 28 04:29:53 localhost nfsdcltrack[14827]: Unable to prepare select statement: no such table: parameters

- nfs-utils-1.3.0-0.41.el7:
[02:11:37 root@ ~~]# cat /var/log/messages | grep 'nfsdcltrack.*Unable'
^^ No warning appears

Move status to VERIFIED according to comment 18 and comment 19, thanks for understanding and the quick fix!

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2017:2233