KitchenPC Logging 101

KitchenPC, as well as most open-source .NET projects, uses log4net for all internal logging.  If you’re already familiar with log4net, most of this post will be fairly useless for you.  Just note you can configure log4net appenders to see various KitchenPC activity.

For the rest of you,  here’s a basic tutorial.  First, you’ll need to reference log4net in your project.  This can be done manually, or by running:

Install-Package log4net

in the NuGet console.

Once you have log4net added to your project, you need to configure it. You can do this in one line of code using:

BasicConfigurator.Configure();

However, this will dump an absolutely insane amount of data to your console which you probably don’t want. Instead, it’s best to configure log4net in your application’s .config file. For this, add the following line of code:

XmlConfigurator.Configure();

Then create the following section in your .config file:

<configSections>
   <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/>
</configSections>

This must appear at the top of the config file, as the first child to the configuration node. You might already have that node, in which case just add the <section> tag. Next, add the following element to the configuration section:

<log4net>
   <appender name="Trace" type="log4net.Appender.ConsoleAppender, log4net">
      <layout type="log4net.Layout.PatternLayout,log4net">
         <param name="ConversionPattern" value="[%level] - %m%n"/>
      </layout>
   </appender>
   <root>
      <level value="ERROR"/>
      <appender-ref ref="Trace"/>
   </root>
   <logger name="KitchenPC.Context">
      <level value="DEBUG"/>
   </logger>
   <logger name="KitchenPC.DB.Provisioning">
      <level value="DEBUG"/>
   </logger>
   <logger name="KitchenPC.NLP">
      <level value="DEBUG"/>
   </logger>
   <logger name="KitchenPC.Modeler">
      <level value="DEBUG"/>
   </logger>
</log4net>

You can control individual configurations of the various KitchenPC loggers. This uses the ConsoleAppender, which writes data out to the console, but log4net comes with various other appenders depending on how you want your data logged, and which events should be logged where. You can read about how to configure these appenders here.

There’s also one more interesting logging feature of KitchenPC, and that’s the NLP tracing logger. The NLP engine is so complicated, it has the ability to trace into individual queries and diagnose exactly how the query was parsed. You can enable an NLP tracer using the NlpTracer.SetTracer() method. This method takes an ITracer implementation which basically has a single method, Trace. The NLP engine will call it if one is configured.

You can write your own ITracer which does whatever you wish with the log data, but there is a default tracer which simply logs each trace event using log4net. Note, this is much more detailed than the standard NLP logging. To configure this trace, you’d use:

NlpTracer.SetTracer(new DefaultTracer()); // Log NLP to log4net

Now if we run the query:

var test = KPCContext.Current.ParseIngredientUsage("a dozen bananas");

We can see the NLP trace:

[DEBUG] - Loaded Template: [ING]
[DEBUG] - Loaded Template: [ING]: [AMT] [UNIT]
[DEBUG] - Loaded Template: [ING]: [AMT]
[DEBUG] - Loaded Template: [FORM] [ING]: [AMT]
[DEBUG] - Loaded Template: [FORM] [ING]: [AMT] [UNIT]
[DEBUG] - Loaded Template: [AMT] [UNIT] [FORM] [ING]
[DEBUG] - Loaded Template: [AMT] [UNIT] [ING]
[DEBUG] - Loaded Template: [AMT] [UNIT] of [ING]
[DEBUG] - Loaded Template: [AMT] [UNIT] of [FORM] [ING]
[DEBUG] - Loaded Template: [AMT] [ING]
[DEBUG] - Loaded Template: [AMT] [UNIT] [FORM], [ING]
[DEBUG] - Loaded Template: [AMT] [FORM] [ING]
[DEBUG] - Loaded Template: [AMT] [ING], [PREP]
[DEBUG] - Loaded Template: [AMT] [UNIT] [ING], [PREP]
[DEBUG] - Loaded Template: [AMT] [UNIT] [FORM] [ING], [PREP]
[DEBUG] - Loaded Template: [AMT] [ING] - [PREP]
[DEBUG] - Loaded Template: [AMT] [UNIT] [ING] - [PREP]
[DEBUG] - Loaded Template: [AMT] [UNIT] [ING] (optional)
[DEBUG] - Loaded Template: [AMT] [UNIT] [FORM] [ING] (optional)
[DEBUG] - Loaded Template: [AMT] [UNIT] [ING] (divided)
[DEBUG] - Loaded Template: [AMT] [UNIT] [ING], divided
[DEBUG] - Loaded Template: [AMT] [UNIT] [ANOMALY]
[DEBUG] - Loaded Template: [AMT] [UNIT] [ANOMALY], [PREP]
[DEBUG] - Loaded Template: [AMT] [UNIT] [ANOMALY] - [PREP]
[DEBUG] - Loaded Template: [AMT] [ANOMALY]
[DEBUG] - Loaded Template: [AMT] [ANOMALY], [PREP]
[DEBUG] - Loaded Template: [AMT] [ANOMALY] - [PREP]
[INFO] - Usage "a dozen bananas" matches the grammar "[AMT] [ING]"
[DEBUG] - [BuildResult] Ingredient: bananas
[DEBUG] - [BuildResult] No custom unit found, so cannot get form based on unit.
[DEBUG] - [BuildResult] No known form found, so cannot get form based on form synonym.
[DEBUG] - [BuildResult] Linking to default Unit paired form 638df06b-780c-4e0d-a3bd-f2986e235fc6
[INFO] - [BuildResult] SUCCESS: Linked form is compatible with usage reference.

Here, we have a successful parse. First, we looped through a bunch of grammar templates to see if any of them matched our input. The template [AMT] [ING] (an amount followed by an ingredient, “a dozen” being an amount and “bananas” being an ingredient) matched. The match data didn’t contain any custom form, such as “slices” or “heads” or what not. In fact, there was no form specified at all, so it was linked with the default form, which is “Units”. Lastly, it verified units of bananas was a valid way to express bananas, which it was, so we have a successful match.

Now, let’s run a query that doesn’t make any sense.

var test = KPCContext.Current.ParseIngredientUsage("5 cheese");

Here, we get the following trace:

[INFO] - Usage "5 cheese" matches the grammar "[AMT] [ING]"
[DEBUG] - [BuildResult] Ingredient: cheese
[DEBUG] - [BuildResult] Re-Link to Root Ingredient: cheddar cheese
[DEBUG] - [BuildResult] No custom unit found, so cannot get form based on unit.
[DEBUG] - [BuildResult] No known form found, so cannot get form based on form synonym.
[DEBUG] - [BuildResult] Could not find any default pairing for the unit type: Unit
[DEBUG] - [BuildResult] Running anomalous parsing.
[DEBUG] - [BuildResult] Could not clarify form through prep note, since unit type is not volumetric or there is no prep note.
[DEBUG] - [BuildResult] Could not auto-convert form since there is no form to convert.
[DEBUG] - [BuildResult] ERROR: Anomalous parsing could still not find a form for this usage.
[INFO] - Could not find match for usage: 5 cheese

Now, the input 5 cheese does match a template. We parsed out the ingredient, which is cheese. However, cheese is an ingredient synonym, so it’s actually resolved to its root ingredient, cheddar cheese. Again, no unit was specified nor any form. However, here’s where we go wrong. There is no default pairing for whole units, as there was with bananas. Meaning, KitchenPC does not know how to process a whole number of cheeses. At this point, we kick in the anomalous parser, which is basically calling in the big guns. Sometimes, we have weird ways to express ingredients that don’t logically make sense, but humans will basically know what it means through intuition. For example, sometimes a prep note can clarify what they mean. An example of this would be something like “3 crushed graham crackers”. Well, in this case, 3 is not a valid measurement for the volumetric form crushed, however graham crackers do have a prep note called crushed, so it’s able to interpret this as “3 graham crackers (crushed)”. In this case, we can’t do this. At this point, the anomalous parser gives up, so we return a result of NoForm. This error indicates we understood the ingredient, but not the form it was expressed in.

Is this useful to you? Well, possibly if you’re tinkering with the NLP parser or adding ingredient data to the database. If not, you can go about your day.