Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat(log): move processing info log to debug level, add builder log #43

Draft
wants to merge 2 commits into
base: main
Choose a base branch
from
Draft

feat(log): move processing info log to debug level, add builder log #43

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
b122238
feat(log): move processing info log to debug level, add builder log
Jun 14, 2021
64841d5
refactor(MaskEngine): rename 'Name' function to 'String'
Jun 15, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
5 changes: 5 additions & 0 deletions CHANGELOG.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -14,6 +14,11 @@ Types of changes
- `Fixed` for any bug fixes.
- `Security` in case of vulnerabilities.

## [1.7.0]

- `Added` Log masks and parameters once at PIMO startup
- `Changed` Process logs move from INFO level to DEBUG level

## [1.6.1]

- `Fixed` Range over array in template mask
Expand Down
2 changes: 1 addition & 1 deletion cmd/pimo/main.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -146,7 +146,6 @@ func run() {
pipeline := model.NewPipeline(source).
Process(model.NewCounterProcessWithCallback("input-line", 0, updateContext)).
Process(model.NewRepeaterProcess(iteration))
over.AddGlobalFields("input-line")

var (
err error
Expand Down Expand Up @@ -190,6 +189,7 @@ func run() {
statistics.Reset()
startTime := time.Now()

over.AddGlobalFields("input-line")
over.AddGlobalFields("output-line")
err = pipeline.AddSink(jsonline.NewSinkWithContext(os.Stdout, "output-line")).Run()

Expand Down
127 changes: 74 additions & 53 deletions demo/demo9/README.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -12,14 +12,18 @@ This can be set with the `-v` flag (long version `--verbosity`) :

```console
$ pimo --empty-input -vinfo
2:57PM INF Logger level set to info
2:57PM INF Start PIMO config=masking.yml dump-cache={} empty-input=true load-cache={} repeat=1 skipFieldOnError=false skipLineOnError=false
2:57PM WRN Path not found config=masking.yml context=empty-input[1] input-line=1 output-line=1 path=name
2:57PM WRN Path not found config=masking.yml context=empty-input[1] input-line=1 output-line=1 path=surname
2:57PM WRN Path not found config=masking.yml context=empty-input[1] input-line=1 output-line=1 path=town
2:57PM WRN Path not found config=masking.yml context=empty-input[1] input-line=1 output-line=1 path=age
9:10PM INF Logger level set to info
9:10PM INF Start PIMO config=masking.yml dump-cache={} empty-input=true load-cache={} repeat=1 skipFieldOnError=false skipLineOnError=false
9:10PM INF Add mask config=masking.yml context=empty-input mask="constant Benjamin" path=name
9:10PM INF Add mask config=masking.yml context=empty-input mask="hash size=2" path=surname
9:10PM INF Add mask config=masking.yml context=empty-input mask="hash size=3" path=town
9:10PM INF Add mask config=masking.yml context=empty-input mask="randomInt min=18 max=90" path=age
9:10PM WRN Path not found config=masking.yml context=empty-input[1] input-line=1 output-line=1 path=name
9:10PM WRN Path not found config=masking.yml context=empty-input[1] input-line=1 output-line=1 path=surname
9:10PM WRN Path not found config=masking.yml context=empty-input[1] input-line=1 output-line=1 path=town
9:10PM WRN Path not found config=masking.yml context=empty-input[1] input-line=1 output-line=1 path=age
{}
2:57PM INF End PIMO config=masking.yml duration=4.0093ms input-line=1 output-line=2 return=0 stats={"ignoredPaths":4,"skippedFields":0,"skippedLines":0}
9:10PM INF End PIMO config=masking.yml duration=12.3069ms input-line=1 output-line=2 return=0 stats={"ignoredPaths":4,"skippedFields":0,"skippedLines":0}
```

By default, the log level is set to error.
Expand Down Expand Up @@ -60,51 +64,59 @@ Event | Log Level | Fields
PIMO starts | `INFO` | All flags used on the command line
PIMO ends successfully | `INFO` | `input-line`, `output-line`, `return`, `stats`, `duration`
PIMO ends unexpectedly | `WARN` | `input-line`, `output-line`, `return`, `duration`
A mask is applied | `INFO` | `input-line`, `output-line`, `context`, `path`
A mask is applied | `DEBUG` | `input-line`, `output-line`, `context`, `path`
A jsonpath point to nothing | `WARN` | `input-line`, `output-line`, `context`, `path`
A line is skipped (`--skip-line-on-error` is used) | `WARN` | `input-line`, `output-line`, `context`, `path`
A field is skipped (`--skip-field-on-error` is used) | `WARN` | `input-line`, `output-line`, `context`, `path`

## Structured logging

With addition of the `--log-json` flag, the logs format will change to JSON.
With addition of the `--log-json` flag, the logs format will change to JSON.

Without `--log-json` flag :

```console
$ echo '{"name": "", "surname": "", "town": "", "age": ""}' | pimo -vinfo --repeat 2
3:26PM INF Logger level set to info
3:26PM INF Start PIMO config=masking.yml dump-cache={} empty-input=false load-cache={} repeat=2 skipFieldOnError=false skipLineOnError=false
3:26PM INF Mask constant config=masking.yml context=stdin[1] input-line=1 output-line=1 path=name
3:26PM INF Mask randomChoice config=masking.yml context=stdin[1] input-line=1 output-line=1 path=surname
3:26PM INF Mask hash config=masking.yml context=stdin[1] input-line=1 output-line=1 path=town
3:26PM INF Mask randomInt config=masking.yml context=stdin[1] input-line=1 output-line=1 path=age
{"age":79,"name":"Benjamin","surname":"Dupont","town":"Ruby City"}
3:26PM INF Mask constant config=masking.yml context=stdin[1] input-line=1 output-line=2 path=name
3:26PM INF Mask randomChoice config=masking.yml context=stdin[1] input-line=1 output-line=2 path=surname
3:26PM INF Mask hash config=masking.yml context=stdin[1] input-line=1 output-line=2 path=town
3:26PM INF Mask randomInt config=masking.yml context=stdin[1] input-line=1 output-line=2 path=age
{"age":53,"name":"Benjamin","surname":"Dupont","town":"Ruby City"}
3:26PM INF End PIMO config=masking.yml duration=10.3316ms input-line=1 output-line=3 return=0 stats={"ignoredPaths":0,"skippedFields":0,"skippedLines":0}
$echo '{"name": "", "surname": "", "town": "", "age": ""}' | pimo -vdebug --repeat 2
9:14PM INF Logger level set to debug
9:14PM INF Start PIMO config=masking.yml dump-cache={} empty-input=false load-cache={} repeat=2 skipFieldOnError=false skipLineOnError=false
9:14PM INF Add mask config=masking.yml context=stdin mask="constant Benjamin" path=name
9:14PM INF Add mask config=masking.yml context=stdin mask="hash size=2" path=surname
9:14PM INF Add mask config=masking.yml context=stdin mask="hash size=3" path=town
9:14PM INF Add mask config=masking.yml context=stdin mask="randomInt min=18 max=90" path=age
9:14PM DBG Mask constant config=masking.yml context=stdin[1] input-line=1 output-line=1 path=name
9:14PM DBG Mask randomChoice config=masking.yml context=stdin[1] input-line=1 output-line=1 path=surname
9:14PM DBG Mask hash config=masking.yml context=stdin[1] input-line=1 output-line=1 path=town
9:14PM DBG Mask randomInt config=masking.yml context=stdin[1] input-line=1 output-line=1 path=age
{"name":"Benjamin","surname":"Dupont","town":"Ruby City","age":79}
9:14PM DBG Mask constant config=masking.yml context=stdin[1] input-line=1 output-line=2 path=name
9:14PM DBG Mask randomChoice config=masking.yml context=stdin[1] input-line=1 output-line=2 path=surname
9:14PM DBG Mask hash config=masking.yml context=stdin[1] input-line=1 output-line=2 path=town
9:14PM DBG Mask randomInt config=masking.yml context=stdin[1] input-line=1 output-line=2 path=age
{"name":"Benjamin","surname":"Dupont","town":"Ruby City","age":53}
9:14PM INF End PIMO config=masking.yml duration=7.2262ms input-line=1 output-line=3 return=0 stats={"ignoredPaths":0,"skippedFields":0,"skippedLines":0}
```

With `--log-json` flag :

```json
$ echo '{"name": "", "surname": "", "town": "", "age": ""}' | pimo -vinfo --log-json --repeat 2
{"level":"info","message":"Logger level set to info"}
$ echo '{"name": "", "surname": "", "town": "", "age": ""}' | pimo -vdebug --log-json --repeat 2
{"level":"info","message":"Logger level set to debug"}
{"level":"info","skipLineOnError":false,"skipFieldOnError":false,"repeat":2,"empty-input":false,"dump-cache":{},"load-cache":{},"config":"masking.yml","message":"Start PIMO"}
{"level":"info","config":"masking.yml","context":"stdin[1]","input-line":"1","output-line":"1","path":"name","message":"Mask constant"}
{"level":"info","config":"masking.yml","context":"stdin[1]","input-line":"1","output-line":"1","path":"surname","message":"Mask randomChoice"}
{"level":"info","config":"masking.yml","context":"stdin[1]","input-line":"1","output-line":"1","path":"town","message":"Mask hash"}
{"level":"info","config":"masking.yml","context":"stdin[1]","input-line":"1","output-line":"1","path":"age","message":"Mask randomInt"}
{"age":79,"name":"Benjamin","surname":"Dupont","town":"Ruby City"}
{"level":"info","config":"masking.yml","context":"stdin[1]","input-line":"1","output-line":"2","path":"name","message":"Mask constant"}
{"level":"info","config":"masking.yml","context":"stdin[1]","input-line":"1","output-line":"2","path":"surname","message":"Mask randomChoice"}
{"level":"info","config":"masking.yml","context":"stdin[1]","input-line":"1","output-line":"2","path":"town","message":"Mask hash"}
{"level":"info","config":"masking.yml","context":"stdin[1]","input-line":"1","output-line":"2","path":"age","message":"Mask randomInt"}
{"age":53,"name":"Benjamin","surname":"Dupont","town":"Ruby City"}
{"level":"info","stats":{"ignoredPaths":0,"skippedLines":0,"skippedFields":0},"return":0,"config":"masking.yml","duration":"10.8207ms","input-line":"1","output-line":"3","message":"End PIMO"}
{"level":"info","path":"name","mask":"constant Benjamin","config":"masking.yml","context":"stdin","message":"Add mask"}
{"level":"info","path":"surname","mask":"hash size=2","config":"masking.yml","context":"stdin","message":"Add mask"}
{"level":"info","path":"town","mask":"hash size=3","config":"masking.yml","context":"stdin","message":"Add mask"}
{"level":"info","path":"age","mask":"randomInt min=18 max=90","config":"masking.yml","context":"stdin","message":"Add mask"}
{"level":"debug","config":"masking.yml","context":"stdin[1]","input-line":"1","output-line":"1","path":"name","message":"Mask constant"}
{"level":"debug","config":"masking.yml","context":"stdin[1]","input-line":"1","output-line":"1","path":"surname","message":"Mask randomChoice"}
{"level":"debug","config":"masking.yml","context":"stdin[1]","input-line":"1","output-line":"1","path":"town","message":"Mask hash"}
{"level":"debug","config":"masking.yml","context":"stdin[1]","input-line":"1","output-line":"1","path":"age","message":"Mask randomInt"}
{"name":"Benjamin","surname":"Dupont","town":"Ruby City","age":79}
{"level":"debug","config":"masking.yml","context":"stdin[1]","input-line":"1","output-line":"2","path":"name","message":"Mask constant"}
{"level":"debug","config":"masking.yml","context":"stdin[1]","input-line":"1","output-line":"2","path":"surname","message":"Mask randomChoice"}
{"level":"debug","config":"masking.yml","context":"stdin[1]","input-line":"1","output-line":"2","path":"town","message":"Mask hash"}
{"level":"debug","config":"masking.yml","context":"stdin[1]","input-line":"1","output-line":"2","path":"age","message":"Mask randomInt"}
{"name":"Benjamin","surname":"Dupont","town":"Ruby City","age":53}
{"level":"info","stats":{"ignoredPaths":0,"skippedLines":0,"skippedFields":0},"return":0,"config":"masking.yml","duration":"5.7093ms","input-line":"1","output-line":"3","message":"End PIMO"}
```

## Structured logging - advanced usage
Expand All @@ -114,37 +126,46 @@ Structured JSON logging enable usages with other JSON-compatible tools like `jq`
In this example, logs are pretty-printed with `mlr --opprint --barred`.

```console
echo '{"name": "", "surname": "", "town": "", "age": ""}' | pimo --log-json -vinfo --repeat 2 2> >(mlr --ijson --opprint --barred cat)
{"age":79,"name":"Benjamin","surname":"Dupont","town":"Ruby City"}
{"age":53,"name":"Benjamin","surname":"Dupont","town":"Ruby City"}
+-------+--------------------------+
| level | message |
+-------+--------------------------+
| info | Logger level set to info |
+-------+--------------------------+
$ echo '{"name": "", "surname": "", "town": "", "age": ""}' | pimo --log-json -vdebug --repeat 2 2> >(mlr --ijson --opprint --barred cat)
{"name":"Benjamin","surname":"Dupont","town":"Ruby City","age":79}
{"name":"Benjamin","surname":"Dupont","town":"Ruby City","age":53}
+-------+---------------------------+
| level | message |
+-------+---------------------------+
| info | Logger level set to debug |
+-------+---------------------------+

+-------+-----------------+------------------+--------+-------------+-------------+------------+
| level | skipLineOnError | skipFieldOnError | repeat | empty-input | config | message |
+-------+-----------------+------------------+--------+-------------+-------------+------------+
| info | false | false | 2 | false | masking.yml | Start PIMO |
+-------+-----------------+------------------+--------+-------------+-------------+------------+

+-------+---------+-------------------------+-------------+---------+----------+
| level | path | mask | config | context | message |
+-------+---------+-------------------------+-------------+---------+----------+
| info | name | constant Benjamin | masking.yml | stdin | Add mask |
| info | surname | hash size=2 | masking.yml | stdin | Add mask |
| info | town | hash size=3 | masking.yml | stdin | Add mask |
| info | age | randomInt min=18 max=90 | masking.yml | stdin | Add mask |
+-------+---------+-------------------------+-------------+---------+----------+

+-------+-------------+----------+------------+-------------+---------+-------------------+
| level | config | context | input-line | output-line | path | message |
+-------+-------------+----------+------------+-------------+---------+-------------------+
| info | masking.yml | stdin[1] | 1 | 1 | name | Mask constant |
| info | masking.yml | stdin[1] | 1 | 1 | surname | Mask randomChoice |
| info | masking.yml | stdin[1] | 1 | 1 | town | Mask hash |
| info | masking.yml | stdin[1] | 1 | 1 | age | Mask randomInt |
| info | masking.yml | stdin[1] | 1 | 2 | name | Mask constant |
| info | masking.yml | stdin[1] | 1 | 2 | surname | Mask randomChoice |
| info | masking.yml | stdin[1] | 1 | 2 | town | Mask hash |
| info | masking.yml | stdin[1] | 1 | 2 | age | Mask randomInt |
| debug | masking.yml | stdin[1] | 1 | 1 | name | Mask constant |
| debug | masking.yml | stdin[1] | 1 | 1 | surname | Mask randomChoice |
| debug | masking.yml | stdin[1] | 1 | 1 | town | Mask hash |
| debug | masking.yml | stdin[1] | 1 | 1 | age | Mask randomInt |
| debug | masking.yml | stdin[1] | 1 | 2 | name | Mask constant |
| debug | masking.yml | stdin[1] | 1 | 2 | surname | Mask randomChoice |
| debug | masking.yml | stdin[1] | 1 | 2 | town | Mask hash |
| debug | masking.yml | stdin[1] | 1 | 2 | age | Mask randomInt |
+-------+-------------+----------+------------+-------------+---------+-------------------+

+-------+--------------------+--------------------+---------------------+--------+-------------+----------+------------+-------------+----------+
| level | stats:ignoredPaths | stats:skippedLines | stats:skippedFields | return | config | duration | input-line | output-line | message |
+-------+--------------------+--------------------+---------------------+--------+-------------+----------+------------+-------------+----------+
| info | 0 | 0 | 0 | 0 | masking.yml | 2.1671ms | 1 | 3 | End PIMO |
| info | 0 | 0 | 0 | 0 | masking.yml | 5.2588ms | 1 | 3 | End PIMO |
+-------+--------------------+--------------------+---------------------+--------+-------------+----------+------------+-------------+----------+
```
8 changes: 7 additions & 1 deletion pkg/add/add.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,8 @@
package add

import (
"fmt"

"github.com/cgi-fr/pimo/pkg/model"
"github.com/rs/zerolog/log"
)
Expand All @@ -34,7 +36,7 @@ func NewMask(value model.Entry) MaskEngine {

// MaskContext add the field
func (am MaskEngine) MaskContext(context model.Dictionary, key string, contexts ...model.Dictionary) (model.Dictionary, error) {
log.Info().Msg("Mask add")
log.Debug().Msg("Mask add")
_, present := context.GetValue(key)
if !present {
context.Set(key, am.value)
Expand All @@ -43,6 +45,10 @@ func (am MaskEngine) MaskContext(context model.Dictionary, key string, contexts
return context, nil
}

func (am MaskEngine) String() string {
return fmt.Sprintf("add %v", am.value)
}

// Create a mask from a configuration
func Factory(conf model.Masking, seed int64, caches map[string]model.Cache) (model.MaskContextEngine, bool, error) {
if conf.Mask.Add != nil {
Expand Down
7 changes: 6 additions & 1 deletion pkg/command/command.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,7 @@
package command

import (
"fmt"
"os/exec"
"strings"

Expand All @@ -37,7 +38,7 @@ func NewMask(cmd string) MaskEngine {

// Mask delegate mask algorithm to an external program
func (cme MaskEngine) Mask(e model.Entry, context ...model.Dictionary) (model.Entry, error) {
log.Info().Msg("Mask command")
log.Debug().Msg("Mask command")
splitCommand := strings.Split(cme.Cmd, " ")
/* #nosec */
out, err := exec.Command(splitCommand[0], splitCommand[1:]...).Output()
Expand All @@ -49,6 +50,10 @@ func (cme MaskEngine) Mask(e model.Entry, context ...model.Dictionary) (model.En
return resulting, nil
}

func (cme MaskEngine) String() string {
return fmt.Sprintf("command %s", cme.Cmd)
}

// Create a mask from a configuration
func Factory(conf model.Masking, seed int64, caches map[string]model.Cache) (model.MaskEngine, bool, error) {
if len(conf.Mask.Command) != 0 {
Expand Down
8 changes: 7 additions & 1 deletion pkg/constant/constant.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,8 @@
package constant

import (
"fmt"

"github.com/cgi-fr/pimo/pkg/model"
"github.com/rs/zerolog/log"
)
Expand All @@ -34,10 +36,14 @@ func NewMask(data model.Entry) MaskEngine {

// Mask return a Constant from a MaskEngine
func (cm MaskEngine) Mask(e model.Entry, context ...model.Dictionary) (model.Entry, error) {
log.Info().Msg("Mask constant")
log.Debug().Msg("Mask constant")
return cm.constValue, nil
}

func (cm MaskEngine) String() string {
return fmt.Sprintf("constant %s", cm.constValue)
}

// Factory create a mask from a configuration
func Factory(conf model.Masking, seed int64, caches map[string]model.Cache) (model.MaskEngine, bool, error) {
if conf.Mask.Constant != nil {
Expand Down
6 changes: 5 additions & 1 deletion pkg/dateparser/dateparser.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -38,7 +38,7 @@ func NewMask(input, output string) MaskEngine {

// Mask change a time format
func (me MaskEngine) Mask(e model.Entry, context ...model.Dictionary) (model.Entry, error) {
log.Info().Msg("Mask dateparser")
log.Debug().Msg("Mask dateparser")
var t time.Time
var err error
if me.inputFormat != "" {
Expand Down Expand Up @@ -66,6 +66,10 @@ func (me MaskEngine) Mask(e model.Entry, context ...model.Dictionary) (model.Ent
return t, nil
}

func (cme MaskEngine) String() string {
return fmt.Sprintf("dateparser inputFormat='%s' outputFormat='%s'", cme.inputFormat, cme.outputFormat)
}

// Factory Create a mask from a configuration
func Factory(conf model.Masking, seed int64, caches map[string]model.Cache) (model.MaskEngine, bool, error) {
if len(conf.Mask.DateParser.InputFormat) != 0 || len(conf.Mask.DateParser.OutputFormat) != 0 {
Expand Down
6 changes: 5 additions & 1 deletion pkg/duration/duration.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -77,7 +77,7 @@ func ParseInt64(value string) int64 {

// Mask masks a time value with a duration
func (dura MaskEngine) Mask(e model.Entry, context ...model.Dictionary) (model.Entry, error) {
log.Info().Msg("Mask duration")
log.Debug().Msg("Mask duration")
var t time.Time
var err error
switch v := e.(type) {
Expand All @@ -94,6 +94,10 @@ func (dura MaskEngine) Mask(e model.Entry, context ...model.Dictionary) (model.E
return t.Add(dura.duration), nil
}

func (dura MaskEngine) String() string {
return fmt.Sprintf("duration %s", dura.duration)
}

// Create a mask from a configuration
func Factory(conf model.Masking, seed int64, caches map[string]model.Cache) (model.MaskEngine, bool, error) {
if len(conf.Mask.Duration) != 0 {
Expand Down
Loading