Implement structured logging with zap #43

alexeyklyukin · 2019-01-04T15:54:51Z

Having a structure in the logs helps to highlight important data (like errors or LSNs), especially when importing to the external log storage.

Another long-standing addition is debug levels, allowing to distinguish between debug and info messages.

This implementation wraps zap around our own logger module. The module's does not define an interface, as there seem no need for it, although it would be trivial to add when necessary (i.e. if we consider plugging another logger or use the same set of functions to pass structured error messages up to the calling functions).

The code is in shape for review, although the actual result may require some fine-tuning on the zap configuration, i.e. removing additional references to the code for the Warn messages. That can be done in an upcoming PR once we settle this one.

The current debug output is quite noisy, particularly because it shows details for every message received. Perhaps it makes sense to have a tri-state of debug/development/production, where development would be a default way to run during development and debug would be useful to diagnose particular issues? The changes also introduce a debug option for the backup and restore, which is off by default (so the default output is terse and is sent as a json, which the debug outputs plain text enriched by parameters).

Another question is how to deal with errors passed upstream that are composed mostly with fmt.Errorf("some error %v when processing the message at LSN %v", err, lsn) and would be displayed differently from the formatted output of "some error when processing the message", {error: "error", "LSN": lsn} emitted by logger/zap. I believe we can settle this in a new pull-request to avoid making this one excessively long.

…ogical_backup with conflicts.

One issue that popped up when examining logical backup is that often we construct error messages with Sprintf before passing them to the upper-level logger. This makes logging inconsistent when taking advantage of the logging field to show parameters like table names or message LSNs.

Add more With functions (WithTableNameString, WithHint). Fix crash at NewLoggerFrom when no withFields arguments are passed. Call sync for loggers on exit.

Move InitGlobalLogger to the logger package.

By defining our logger we can take advantage of With functions and avoid excessive imports of zap. Minor cleanup all over the place, mostly replacing zap's With with our own With.. functions and changing *f functions to plain ones where possible.

ghost

Found some fixes!

P.S. share your ideas, feedbacks or issues with us at https://github.com/fixmie/feedback (this message will be removed after the beta stage).

ghost

Found some fixes!

P.S. share your ideas, feedbacks or issues with us at https://github.com/fixmie/feedback (this message will be removed after the beta stage).

alexeyklyukin · 2019-01-07T06:57:08Z

pkg/logger/logger.go

+}
+
+// PrintMessageForDebug emits a log entry describing the current message received for debug purposes.
+func PrintMessageForDebug(prefix string, msg message.Message, currentLSN dbutils.LSN, log *Log) {


looks like to bot went bonkers here, reported and ignoring this one.

alexeyklyukin · 2019-01-07T06:57:08Z

pkg/logger/logger.go

+}
+
+// PrintMessageForDebug emits a log entry describing the current message received for debug purposes.
+func PrintMessageForDebug(prefix string, msg message.Message, currentLSN dbutils.LSN, log *Log) {


looks like to bot went bonkers here, reported and ignoring this one.

mkabilov · 2019-01-07T10:29:02Z

pkg/config/config.go

-		log.Printf("Staging directory: %q", c.StagingDir)
-	} else {
-		log.Printf("No staging directory. Writing directly to the archive dir")
+	ops := [][]string{


map[string]string

That was my initial choice, but map does not preserve the order and I don't want help screen to be sorted by random()

but the current implementation along with ops = ops[1:] is ugly

IMO it's less ugly than a bunch of unstructured log.Printfs, although I'll think about improving it.

TBH I don't see a problem with bunch of logger.G.With(<param>, <value>).Info("option")

what you really can do to improve that part, is to make use of reflect to iterate over config struct fields

The problem with a bunch of logger statements is that they promote unnecessary repetitions and shift the solution to writing more code instead of using proper data structures . The list solution is adequate, albeit some ugly parts you've highlighted; the reflection would neither solve the issue (as we don't output the literal name of the parameter, but some human-readable variation of it), nor simplify the code. Instead, I'm changing it back to maps and just sorting by keys to ensure a consistent output on every run.

Turns out map approach doesn't buy us much in terms of readability, as it is not possible to write a function like ternary(ptr != nil, fmt.Sprintf("%v", *ptr), "") without crashing if ptr is null, reverted back to just show each parameter in a separate log.

mkabilov · 2019-01-07T10:29:36Z

pkg/config/config.go

 	if cfg.PrometheusPort == 0 {
 		cfg.PrometheusPort = defaultPrometheusPort
 	}
+	if debug {


if makes no sense here. bool is initialized with the false value

I don't want to overwrite explicitly set to true cfg.Debug with a default (false) value from a command-line.

mkabilov · 2019-01-07T10:30:41Z

pkg/logger/logger.go

+	} else {
+		logger, err = zap.NewProduction()
+	}
+	if err == nil {


I'd do vice versa: check if there's an error here

mkabilov · 2019-01-07T10:31:31Z

test/test.sh


  psql -d postgres -c "drop database if exists lb_test1;"
  psql -d postgres -c "drop database if exists lb_test2;"
-}


I'd create separate PR for the changes in the test script

Hm....good catch, I didn't intend to change anything in the test.

mkabilov · 2019-01-07T10:36:08Z

cmd/restore/main.go

 	schemaName = flag.String("schema", "public", "Schema name")
 	targetTable = flag.String("target-table", "", "Target table name (optional)")
 	backupDir = flag.String("backup-dir", "", "Backups dir")
+	debug = flag.Bool("debug", false, "Toggle debug mode")


Ideally there should be loglevel instead of just debug

Those were added in the latest commit.

Disable stack traces for warn level, allow setting minimum log level and disabling emitting source code line numbers in the log. Additional YAML configuration parameters for the backup and command-line for the restore to customize logging. As a collaterial to refining log messages, set the String() output of TableBackup to show unsanitized string representation, avoiding extra quotes in the logs (so far this function is only used for logging). Some minor stylistic changes around previously ignored errors in printf in the files touched by other changes.

ghost

Found some fixes!

P.S. share your ideas, feedbacks or issues with us at https://github.com/fixmie/feedback (this message will be removed after the beta stage).

fatih · 2019-01-08T12:20:21Z

pkg/tablebackup/tablebackup.go

-	dbCfg pgx.ConnConfig, basebackupsQueue *queue.Queue, prom promexporter.PrometheusExporterInterface) (*TableBackup, error) {
-	tableDir := utils.TableDir(oid)
+// New constructs a new TableBackup instance.
+func New(ctx context.Context, group *sync.WaitGroup,


Hi 👋 This is a bug, I'm planning to fix it tonight. Sorry for the inconvenience. In the future, if you can report these kind of bugs (https://github.com/fixmie/feedback), I could learn it earlier and would appreciate it :)

fatih · 2019-01-08T12:20:21Z

pkg/tablebackup/tablebackup.go

-	dbCfg pgx.ConnConfig, basebackupsQueue *queue.Queue, prom promexporter.PrometheusExporterInterface) (*TableBackup, error) {
-	tableDir := utils.TableDir(oid)
+// New constructs a new TableBackup instance.
+func New(ctx context.Context, group *sync.WaitGroup,


Hi 👋 This is a bug, I'm planning to fix it tonight. Sorry for the inconvenience. In the future, if you can report these kind of bugs (https://github.com/fixmie/feedback), I could learn it earlier and would appreciate it :)

Naive approaches of putting them in a slice or a map before printing haven't produced either shorter or more readable code, partially because incapsulating a check into a ternary-operator like function is not possible with go, as the language evaluations function arguments at call time. We may revisit this code one day to fetch the description from the Config struct using reflection and to separate validation of arguments from the actual printing.

ghost

Found some fixes!

P.S. share your ideas, feedbacks or issues with us at https://github.com/fixmie/feedback (this message will be removed after the beta stage).

alexeyklyukin · 2019-01-11T16:40:45Z

Closed in favor of #50

Alex Kliukin added 8 commits January 2, 2019 10:43

Merge branch 'master' of /Users/alexk/src/go/src/github.com/ikitiki/l…

6787e17

…ogical_backup with conflicts.

Make sure the logger is also created when debug is turned off.

d9ea7b0

Crete a new logger class to simplify logging well-known parameters

c7e7777

Use logger for config, covert the rest of the backup code.

9137778

Add more With functions (WithTableNameString, WithHint). Fix crash at NewLoggerFrom when no withFields arguments are passed. Call sync for loggers on exit.

Add zap to logicalrestore.

36ceac7

Move InitGlobalLogger to the logger package.

Minor fine-tuning

1d32bc6

ghost reviewed Jan 4, 2019

View reviewed changes

Fix a few comments, per gripe from the fixmie bot.

b8c89af

ghost reviewed Jan 7, 2019

View reviewed changes

alexeyklyukin commented Jan 7, 2019

View reviewed changes

One more missing comment, per gripe from the fixmie bot.

36f31bd

mkabilov reviewed Jan 7, 2019

View reviewed changes

alexeyklyukin and others added 2 commits January 7, 2019 17:48

Revert inadvertent changes to the test script.

9139593

ghost reviewed Jan 8, 2019

View reviewed changes

Repository owner deleted a comment Jan 8, 2019

fatih reviewed Jan 8, 2019

View reviewed changes

ghost reviewed Jan 8, 2019

View reviewed changes

Oleksii Kliukin and others added 3 commits January 8, 2019 14:07

Add missing newline at the end

8b1b0d4

Merge branch 'master' into zap

c66298b

Tie up loose ends from the merge. Commit the zap vendor subfolders.

e110833

alexeyklyukin closed this Jan 11, 2019

Implement structured logging with zap #43

Implement structured logging with zap #43

Uh oh!

Conversation

alexeyklyukin commented Jan 4, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

ghost left a comment

Choose a reason for hiding this comment

Uh oh!

ghost left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mkabilov Jan 7, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mkabilov Jan 7, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ghost left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ghost left a comment

Choose a reason for hiding this comment

Uh oh!

alexeyklyukin commented Jan 11, 2019

Uh oh!

Uh oh!

alexeyklyukin commented Jan 4, 2019 •

edited

Loading

mkabilov Jan 7, 2019 •

edited

Loading

mkabilov Jan 7, 2019 •

edited

Loading