Обсуждение: logging of Logical Decoding

On 12/24/2014 02:29 AM, Andrey Lizenko wrote:
> Hello,
> every execute of 'pg_logical_slot_get_changes'  is logged by
>
>     2014-12-23 11:41:53 EST STATEMENT:  SELECT * FROM
>     pg_logical_slot_get_changes('regression_slot', NULL, NULL);
>     2014-12-23 11:42:21 EST LOG:  starting logical decoding for slot
>     "regression_slot"
>     2014-12-23 11:42:21 EST DETAIL:  streaming transactions committing
>     after A/4E026FD8, reading WAL from A/4E026ED0
>
>
>
> logs settings are almost default:
>
>     postgres=# select name, setting from pg_settings where name like
>     ('log%');
>                  name             |            setting
>     -----------------------------+--------------------------------
>       log_autovacuum_min_duration | -1
>       log_checkpoints             | off
>       log_connections             | off
>       log_destination             | stderr
>       log_directory               | pg_log
>       log_disconnections          | off
>       log_duration                | off
>       log_error_verbosity         | default
>       log_executor_stats          | off
>       log_file_mode               | 0600
>       log_filename                | postgresql-%Y-%m-%d_%H%M%S.log
>       log_hostname                | off
>       log_line_prefix             |  %t
>       log_lock_waits              | off
>       log_min_duration_statement  | -1
>       log_min_error_statement     | error
>       log_min_messages            | warning
>       log_parser_stats            | off
>       log_planner_stats           | off
>       log_rotation_age            | 1440
>       log_rotation_size           | 10240
>       log_statement               | none
>       log_statement_stats         | off
>       log_temp_files              | -1
>       log_timezone                | US/Eastern
>       log_truncate_on_rotation    | off
>       logging_collector           | off
>     (27 rows)
>
>
> Is it possible to reduce verbose level for this?

Set log_error_verbosity to terse:

http://www.postgresql.org/docs/9.4/interactive/runtime-config-logging.html

log_error_verbosity (enum)

     Controls the amount of detail written in the server log for each
message that is logged. Valid values are TERSE, DEFAULT, and VERBOSE,
each adding more fields to displayed messages. TERSE excludes the
logging of DETAIL, HINT, QUERY, and CONTEXT error information. VERBOSE
output includes the SQLSTATE error code (see also Appendix A) and the
source code file name, function name, and line number that generated the
error. Only superusers can change this setting.


Sort of surprised that the SELECT showed up when log_statement = none.

Did you reload Postgres after making changes to the config?

>
> Server version is 9.4.0, OS is Ubuntu 12.04 LTS
>
>
>
> --
> Regards, Andrey Lizenko


--
Adrian Klaver
adrian.klaver@aklaver.com

On 12/24/2014 07:53 AM, Andrey Lizenko wrote:
> I've restarted server once again to be sure.
>
> For this commands:
>
>     postgres@ubuntu12-vm:/mnt/data4$ psql
>     psql (9.4.0)
>     Type "help" for help.
>     postgres=# show log_error_verbosity ;
>       log_error_verbosity
>     ---------------------
>       terse
>     (1 row)
>     postgres=# SELECT * FROM
>     pg_logical_slot_get_changes('regression_slot', NULL, NULL);
>       location | xid | data
>     ----------+-----+------
>     (0 rows)
>
>
> I can see the following log:
>
>       2014-12-24 10:45:01 EST LOG:  database system was shut down at
>     2014-12-24 10:44:52 EST
>       2014-12-24 10:45:01 EST LOG:  database system is ready to accept
>     connections
>       2014-12-24 10:45:01 EST LOG:  autovacuum launcher started
>       2014-12-24 10:45:23 EST LOG:  starting logical decoding for slot
>     "regression_slot"
>       2014-12-24 10:45:23 EST STATEMENT:  SELECT * FROM
>     pg_logical_slot_get_changes('regression_slot', NULL, NULL);
>       2014-12-24 10:45:23 EST LOG:  logical decoding found consistent
>     point at A/75000100
>       2014-12-24 10:45:23 EST STATEMENT:  SELECT * FROM
>     pg_logical_slot_get_changes('regression_slot', NULL, NULL);
>
>
> So it seems terse verbosity doesn't help. Bug? Or something wrong in my
> config? As I said before, it is created from scratch and almost default,
> expect log_line_prefix

Well you wanted to reduce verbosity level which is what happens when you
set to terse.

What you are looking for is to eliminate logging the statement entirely?

I would have though having log_statement = none would prevent that.

Someone else will have to comment on why that is not so?

>
>



--
Adrian Klaver
adrian.klaver@aklaver.com

Adrian Klaver <adrian.klaver@aklaver.com> writes:
> On 12/24/2014 07:53 AM, Andrey Lizenko wrote:
>> 2014-12-24 10:45:23 EST LOG:  starting logical decoding for slot
>> "regression_slot"
>> 2014-12-24 10:45:23 EST STATEMENT:  SELECT * FROM
>> pg_logical_slot_get_changes('regression_slot', NULL, NULL);
>> 2014-12-24 10:45:23 EST LOG:  logical decoding found consistent
>> point at A/75000100
>> 2014-12-24 10:45:23 EST STATEMENT:  SELECT * FROM
>> pg_logical_slot_get_changes('regression_slot', NULL, NULL);

> What you are looking for is to eliminate logging the statement entirely?
> I would have though having log_statement = none would prevent that.

No, this isn't logging any old statement that comes along, it's logging
the statement that provoked the LOG message.  That's normal behavior.

It is worth asking why these messages aren't DEBUG rather than LOG,
but I don't see anything unexpected about the form of the output.

            regards, tom lane

On 12/24/2014 08:50 AM, Tom Lane wrote:
> Adrian Klaver <adrian.klaver@aklaver.com> writes:
>> On 12/24/2014 07:53 AM, Andrey Lizenko wrote:
>>> 2014-12-24 10:45:23 EST LOG:  starting logical decoding for slot
>>> "regression_slot"
>>> 2014-12-24 10:45:23 EST STATEMENT:  SELECT * FROM
>>> pg_logical_slot_get_changes('regression_slot', NULL, NULL);
>>> 2014-12-24 10:45:23 EST LOG:  logical decoding found consistent
>>> point at A/75000100
>>> 2014-12-24 10:45:23 EST STATEMENT:  SELECT * FROM
>>> pg_logical_slot_get_changes('regression_slot', NULL, NULL);
>
>> What you are looking for is to eliminate logging the statement entirely?
>> I would have though having log_statement = none would prevent that.
>
> No, this isn't logging any old statement that comes along, it's logging
> the statement that provoked the LOG message.  That's normal behavior.

Hmm, I missed the connection between starting logical decoding and
pg_logical_slot_get_changes. Time to do more reading on logical decoding.

>
> It is worth asking why these messages aren't DEBUG rather than LOG,
> but I don't see anything unexpected about the form of the output.
>
>             regards, tom lane
>


--
Adrian Klaver
adrian.klaver@aklaver.com