View Issue Details

IDProjectCategoryView StatusLast Update
0000606Pgpool-IIBugpublic2020-05-01 20:47
ReporterpehrsAssigned Tot-ishii 
PrioritylowSeveritytweakReproducibilityalways
Status resolvedResolutionopen 
PlatformLinuxOSUbuntu OS Version19.10
Product Version4.1.0 
Target Version4.1.2Fixed in Version 
Summary0000606: Log spam from successful authentication
DescriptionThe log level for successful authentication with a front end server is "LOG", seems a bit too high. It results in log spam like this on a reasonably active server:

2020-04-23T11:27:01.036830+02:00 db-02 pgpool[25799]: 2020-04-23 11:27:01: pid 35822:LOG: md5 authentication successful with frontend
2020-04-23T11:27:01.317006+02:00 db-02 pgpool[25799]: 2020-04-23 11:27:01: pid 25076:LOG: md5 authentication successful with frontend
2020-04-23T11:27:01.414691+02:00 db-02 pgpool[25799]: 2020-04-23 11:27:01: pid 32317:LOG: md5 authentication successful with frontend
2020-04-23T11:27:01.597430+02:00 db-02 pgpool[25799]: 2020-04-23 11:27:01: pid 26346:LOG: md5 authentication successful with frontend
2020-04-23T11:27:01.599374+02:00 db-02 pgpool[25799]: 2020-04-23 11:27:01: pid 35925:LOG: md5 authentication successful with frontend
2020-04-23T11:27:01.613934+02:00 db-02 pgpool[25799]: 2020-04-23 11:27:01: pid 26328:LOG: md5 authentication successful with frontend
2020-04-23T11:27:01.653750+02:00 db-02 pgpool[25799]: 2020-04-23 11:27:01: pid 26340:LOG: md5 authentication successful with frontend
2020-04-23T11:27:01.657373+02:00 db-02 pgpool[25799]: 2020-04-23 11:27:01: pid 26329:LOG: md5 authentication successful with frontend
2020-04-23T11:27:01.732492+02:00 db-02 pgpool[25799]: 2020-04-23 11:27:01: pid 26338:LOG: md5 authentication successful with frontend
2020-04-23T11:27:01.846211+02:00 db-02 pgpool[25799]: 2020-04-23 11:27:01: pid 26343:LOG: md5 authentication successful with frontend

As the "LOG" log level doesn't exist in syslog, it is not quite clear how to get rid of the spam. pgpool.conf.sample gives the following information regarding the log levels:

log_min_messages = warning # values in order of decreasing detail:
                                        # debug5
                                        # debug4
                                        # debug3
                                        # debug2
                                        # debug1
                                        # info
                                        # notice
                    # warning
                    # error
                                        # log
                                        # fatal
                                        # panic

Which indicates that LOG Is higher than error. When looking at the code:

    pg_md5_encrypt(md5 + strlen("md5"), salt, sizeof(salt), encbuf);
        if (strcmp(password, encbuf))
        {
                /* Password does not match */
                ereport(ERROR,
                                (errmsg("md5 authentication failed"),
                                 errdetail("password does not match")));
        }
        ereport(LOG,
                        (errmsg("md5 authentication successful with frontend")));

This indicates that logging successful authentication attempts take priority over logging failed ones. And that seems rather backwards, as I would certainly want to know about failed authentication attempts.

At this point I am rather stumped:
1. Should LOG really have such high priory, and should the priority order really differ between client_min_messages and log_min_messages?
2. Is there a reason we would want to log successful authentication with higher priority than failed authentication?
Steps To Reproduce1. Setup pgpool
2. Enable logging
3. Point a reasonably active server at the pgpool
4. Look at the log spam.
TagsNo tags attached.

Activities

t-ishii

2020-04-25 20:07

developer   ~0003341

> 1. Should LOG really have such high priory, and should the priority order really differ between client_min_messages and log_min_messages?
We follow the priority order as PostgreSQL does.

> 2. Is there a reason we would want to log successful authentication with higher priority than failed authentication?
I think logs for successful authentication should be downgraded to DEBUG1 or something like that. Let me discuss with Pgpool-II developers.

pehrs

2020-04-25 20:50

reporter   ~0003342

> I think logs for successful authentication should be downgraded to DEBUG1 or something like that. Let me discuss with Pgpool-II developers.

Thank you for the prompt reply and an awesome system. This might just be a minor QoL fix, but it that makes my life as a user easier.

t-ishii

2020-04-26 11:35

developer   ~0003343

I have pushed a fix.
https://git.postgresql.org/gitweb/?p=pgpool2.git;a=commit;h=311cdc7a49b4219ee819ea137c5f9d4837852fa5

Next release 4.1.2 will include the fix (supposed to be released on May 21).

pehrs

2020-04-26 17:18

reporter   ~0003344

Thank you. It sounds like it will resolve my issue when it is released!

t-ishii

2020-05-01 17:30

developer   ~0003346

May I change the status of this issue to "resolved"?

pehrs

2020-05-01 20:16

reporter   ~0003349

@t-ishii Please do.

Issue History

Date Modified Username Field Change
2020-04-23 19:30 pehrs New Issue
2020-04-25 20:02 t-ishii Assigned To => t-ishii
2020-04-25 20:02 t-ishii Status new => assigned
2020-04-25 20:07 t-ishii Note Added: 0003341
2020-04-25 20:07 t-ishii Status assigned => feedback
2020-04-25 20:50 pehrs Note Added: 0003342
2020-04-25 20:50 pehrs Status feedback => assigned
2020-04-26 11:32 t-ishii Target Version => 4.1.2
2020-04-26 11:35 t-ishii Note Added: 0003343
2020-04-26 11:35 t-ishii Status assigned => feedback
2020-04-26 17:18 pehrs Note Added: 0003344
2020-04-26 17:18 pehrs Status feedback => assigned
2020-05-01 17:30 t-ishii Note Added: 0003346
2020-05-01 17:31 t-ishii Status assigned => feedback
2020-05-01 20:16 pehrs Note Added: 0003349
2020-05-01 20:16 pehrs Status feedback => assigned
2020-05-01 20:47 t-ishii Status assigned => resolved