Metafix logs too much by default when log level is set to debug

[TobiasNx]

On "Debug"-Level Metafix seems to log too much, is this intended, normally flux-commands do not provide any internal logging:

"https://github.com/LibreCat/Catmandu/wiki/files/camel.usmarc"
| open-http(encoding="ascii")
| as-lines
| match(pattern="\\A(.{9}) ", replacement="$1a")
| decode-marc21
| fix("
	nothing()"
)
| encode-yaml
| print
;

--->

$ '/home/user/git/metafacture-core/metafacture-runner/build/install/metafacture-core/flux.sh' '/home/user/git/metafacture_workflows/usMarc/usmarc.flux'
DEBUG [main] [AbstractInternalAntlrParser] Parsing took: 15 ms
DEBUG [main] [AbstractCleaningLinker] beforeModelLinked took: 0ms
DEBUG [main] [AbstractCleaningLinker] doLinkModel took: 5ms
DEBUG [main] [AbstractCleaningLinker] afterModelLinked took: 0ms
DEBUG [main] [ResourceValidatorImpl] Syntax check OK! Resource: file:/tmp/metafix14978692744312842593.fix
DEBUG [main] [Metafix] Start record: fol05731351 
DEBUG [main] [Metafix] Putting 'status': 'c'
DEBUG [main] [Metafix] Putting 'type': 'a'
DEBUG [main] [Metafix] Putting 'bibliographicLevel': 'm'
DEBUG [main] [Metafix] Putting 'typeOfControl': ' '
DEBUG [main] [Metafix] Putting 'characterCodingScheme': 'a'
DEBUG [main] [Metafix] Putting 'encodingLevel': '4'
DEBUG [main] [Metafix] Putting 'catalogingForm': 'a'
DEBUG [main] [Metafix] Putting 'multipartLevel': ' '
DEBUG [main] [Metafix] Putting '001': 'fol05731351 '
DEBUG [main] [Metafix] Putting '003': 'IMchF'
DEBUG [main] [Metafix] Putting '005': '20000613133448.0'
DEBUG [main] [Metafix] Putting '008': '000107s2000    nyua          001 0 eng  '
DEBUG [main] [Metafix] Putting 'a': '   00020737 '
DEBUG [main] [Metafix] Putting 'a': '0471383147 (paper/cd-rom : alk. paper)'
DEBUG [main] [Metafix] Putting 'a': 'DLC'
DEBUG [main] [Metafix] Putting 'c': 'DLC'
DEBUG [main] [Metafix] Putting 'd': 'DLC'
DEBUG [main] [Metafix] Putting 'a': 'pcc'
DEBUG [main] [Metafix] Putting 'a': 'QA76.73.P22'
DEBUG [main] [Metafix] Putting 'b': 'M33 2000'
DEBUG [main] [Metafix] Putting 'a': '005.13/3'
DEBUG [main] [Metafix] Putting '2': '21'
DEBUG [main] [Metafix] Putting 'a': 'Martinsson, Tobias,'
DEBUG [main] [Metafix] Putting 'd': '1976-'
DEBUG [main] [Metafix] Putting 'a': 'ActivePerl with ASP and ADO /'
DEBUG [main] [Metafix] Putting 'c': 'Tobias Martinsson.'
DEBUG [main] [Metafix] Putting 'a': 'New York :'
DEBUG [main] [Metafix] Putting 'b': 'John Wiley & Sons,'
DEBUG [main] [Metafix] Putting 'c': '2000.'
DEBUG [main] [Metafix] Putting 'a': 'xxi, 289 p. :'
DEBUG [main] [Metafix] Putting 'b': 'ill. ;'
DEBUG [main] [Metafix] Putting 'c': '23 cm. +'
DEBUG [main] [Metafix] Putting 'e': '1 computer  laser disc (4 3/4 in.)'
DEBUG [main] [Metafix] Putting 'a': '"Wiley Computer Publishing."'
DEBUG [main] [Metafix] Putting 'a': 'Perl (Computer program language)'
DEBUG [main] [Metafix] Putting 'a': 'Active server pages.'
DEBUG [main] [Metafix] Putting 'a': 'ActiveX.'
DEBUG [main] [Metafix] End record, walking Fix: {leader={status=c, type=a, bibliographicLevel=m, typeOfControl= , characterCodingScheme=a, encodingLevel=4, catalogingForm=a, multipartLevel= }, 001=fol05731351 , 003=IMchF, 005=20000613133448.0, 008=000107s2000    nyua          001 0 eng  , 010  ={a=   00020737 }, 020  ={a=0471383147 (paper/cd-rom : alk. paper)}, 040  ={a=DLC, c=DLC, d=DLC}, 042  ={a=pcc}, 05000={a=QA76.73.P22, b=M33 2000}, 08200={a=005.13/3, 2=21}, 1001 ={a=Martinsson, Tobias,, d=1976-}, 24510={a=ActivePerl with ASP and ADO /, c=Tobias Martinsson.}, 260  ={a=New York :, b=John Wiley & Sons,, c=2000.}, 300  ={a=xxi, 289 p. :, b=ill. ;, c=23 cm. +, e=1 computer  laser disc (4 3/4 in.)}, 500  ={a="Wiley Computer Publishing."}, 650 0={a=Perl (Computer program language)}, 63000=[{a=Active server pages.}, {a=ActiveX.}]}
DEBUG [main] [Metafix] Sending results to org.metafacture.yaml.YamlEncoder@65629ac6
---
leader:
  status: "c"
  type: "a"
  bibliographicLevel: "m"
  typeOfControl: " "
  characterCodingScheme: "a"
  encodingLevel: "4"
  catalogingForm: "a"
  multipartLevel: " "
"001": "fol05731351 "
"003": "IMchF"
"005": "20000613133448.0"
"008": "000107s2000    nyua          001 0 eng  "
"010  ":
  a: "   00020737 "
"020  ":
  a: "0471383147 (paper/cd-rom : alk. paper)"
"040  ":
  a: "DLC"
  c: "DLC"
  d: "DLC"
"042  ":
  a: "pcc"
"05000":
  a: "QA76.73.P22"
  b: "M33 2000"
"08200":
  a: "005.13/3"
  "2": "21"
"1001 ":
  a: "Martinsson, Tobias,"
  d: "1976-"
"24510":
  a: "ActivePerl with ASP and ADO /"
  c: "Tobias Martinsson."
"260  ":
  a: "New York :"
  b: "John Wiley & Sons,"
  c: "2000."
"300  ":
  a: "xxi, 289 p. :"
  b: "ill. ;"
  c: "23 cm. +"
  e: "1 computer  laser disc (4 3/4 in.)"
"500  ":
  a: "\"Wiley Computer Publishing.\""
"650 0":
  a: "Perl (Computer program language)"
"63000":
  a: "Active server pages."
"63000":
  a: "ActiveX."

Originally posted by @TobiasNx in #733 (comment)

In contrast to other flux commands fix is logging a lot by default. This overcrowds the logs.

[blackwinter]

As already mentioned in #733 (comment), the core issue is that you as a user don't want/need to see these logs. They're meant for developers, and possibly for "users" of Metafacture as a library. (Aside: These internal logs may also be reassessed in relation to already available logging infrastructure such as log-stream.)

So we need to think about decoupling end-user logs from log commands (log-stream, log-object etc.) and functions (log) from those emitted by internal loggers.

[TobiasNx]

You are right but still the pattern, that the other flux commands do not behave as fix does, seems to be an indicator that the logging is implemented differently.

[blackwinter]

the pattern, that the other flux commands do not behave as fix does, seems to be an indicator that the logging is implemented differently.

That's not entirely true, there is some precedent from before the introduction of Metafix:

• JsonValidator:

  LOG.debug("Success: {}, Fail: {}", success, fail);
  LOG.debug("Could not read as URL: {}, trying to load from class path", schemaUrl);
  LOG.info("Invalid JSON: {} in {}", errorMessage, object != null ? object.opt(idKey) : json);

• Metamorph:

  LOG.warn("Only one of '_else', '_elseFlattened' and '_elseNested' is allowed. Ignoring the superflous ones.");

• ObjectPipeDecoupler:

  LOG.info("Current buffer size: {}", queue.size());

• ObjectThreader:

  LOG.info("Adding thread {}", receivers.size() + 1);

• XmlFilenameWriter:

  LOG.info("No identifier found, skip writing");
  LOG.debug("the xml: {}", xml);

[blackwinter]

The simplest solution right now would probably be to either 1) exclude all loggers that (currently) only log internal messages, or 2) only include those loggers that (currently) log end-user oriented messages.

1. Exclusion (default level INFO, negative override with WARN):

   <logger name="org.metafacture.metafix.Metafix">
       <level value="warn" />
   </logger>
   [...]
   <root>
       <priority value="info" />
       <appender-ref ref="stdout" />
   </root>

2. Inclusion (default level WARN, positive override with INFO):

   <logger name="org.metafacture.monitoring.StreamLogger">
       <level value="info" />
   </logger>
   [...]
   <root>
       <priority value="warn" />
       <appender-ref ref="stdout" />
   </root>

For a long-term solution, though, we might rather want to look into establishing separate Logger instances with their own naming convention, which then allows for a more targeted configuration. BUT: Before we follow down that path, we should really consider upgrading Log4j (or even switching to a different logging provider) first.

[TobiasNx]

You are right some modules provide internal logging info. If I oversee the logging above correctly there are some informations that are interesting for user.

Also when comparing the morph and the fix internal logging fix give a lot more back. It provides the composition for every record:

[AbstractInternalAntlrParser]
[AbstractCleaningLinker]
[ResourceValidatorImpl]

The hole construction of the record:

DEBUG [main] [Metafix] Start record: fol05731351 
DEBUG [main] [Metafix] Putting ...
...

And that it sends the stuff to the next modul
DEBUG [main] [Metafix] Sending results to org.metafacture.yaml.YamlEncoder@65629ac6

[blackwinter]

Functional review: @TobiasNx
Code review: @fsteeg