Kinesis client app not logging+

[andyg75]

We are using your ReactoKinesiX library for our C# Kinesis Consumer application. The application appears to be properly configured to initialize log4net, but nothing is being written to the log file we have configured.

In our AssemblyInfo.cs, we have included the following: [assembly: log4net.Config.XmlConfigurator(ConfigFile = "Log4Net.config", Watch = true)]

In our C# application, when starting the consumer, we do this:

System.IO.FileInfo log4netName = new System.IO.FileInfo("Log4Net.config");
XmlConfigurator.Configure(log4netName);
factory = new DBBufferAccumulatorFactory();
var accumulator = new DBBufferAccumulator();
accumulator.StartRecordProcessing();
DBBufferAccumulator.AwsEnvironment = AwsEnvironment;
// Start a timer to flush the list to database.
app = factory.RegisterWithKinesis(appName, streamName, workerId, awsEnvironment);
accumulator.StartTimer(seconds);

We have a file named Log4Net.config in the root folder of our application.

<?xml version="1.0" encoding="utf-8"?>
<configuration>
  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler,Log4net"/>
  </configSections> 
<log4net>
    <appender name="LogFileAppender" type="log4net.Appender.RollingFileAppender">
      <param name="File" value="C:\logfiles\%Y-%m\%Y%m%d\kinesis.log" />
      <param name="AppendToFile" value="true" />
      <rollingStyle value="Size" />
      <maxSizeRollBackups value="10" />
      <maximumFileSize value="100MB" />
      <staticLogFileName value="true" />
      <layout type="log4net.Layout.PatternLayout">
        <param name="ConversionPattern" value="%-5p%d{yyyy-MM-dd hh:mm:ss} – %m%n" />
      </layout>
    </appender>
    <root>
      <level value="DEBUG" />
      <appender-ref name="LogFileAppender" />
    </root>
  </log4net>
</configuration>

I'm at a loss here as to what we might be doing wrong...

[theburningmonk]

hey, what version of log4net are you using? It might just need a bindind redirect if it's using a different version to the one the library is depending on.

Does running nuget command to add binding-redirect add anything to your app.config?

[andyg75]

We are using 1.2.13. I will try nuget with binding-redirect when we get to a good pause point in the current SQA cycle. Thanks very much for your reply.

[andyg75]

I ran "Add-BindingRedirect" for the project and it spat out AWSSDK, System.Reactive.Linq, and System.Reactive.Core in the console. It marked the App.Config as modified, but it didn't actually make any changes. Here's the app.config section for assembly binding.

<assemblyBinding xmlns="urn:schemas-microsoft-com:asm.v1">
  <dependentAssembly>
    <assemblyIdentity name="System.Reactive.Linq" publicKeyToken="31bf3856ad364e35" culture="neutral" />
    <bindingRedirect oldVersion="0.0.0.0-2.2.0.0" newVersion="2.2.0.0" />
  </dependentAssembly>
  <dependentAssembly>
    <assemblyIdentity name="System.Reactive.Core" publicKeyToken="31bf3856ad364e35" culture="neutral" />
    <bindingRedirect oldVersion="0.0.0.0-2.2.0.0" newVersion="2.2.0.0" />
  </dependentAssembly>
</assemblyBinding>

The "manage packages" dialog box shows that we do have log4net [1.2.13], which I believe is the same one that v 0.3.0 of your library depends on. The only odd thing I see is FSharp.Reactive version 2.2.131002 is marked as [Obsolete].

[andyg75]

This info may be useful: our Kinesis consumer application runs as a static class inside of a custom built "code runner" service (a la (but predating) AWS Lambda). Aside from the log4net.config file which I mentioned above, the only config file present on the machine that runs the Kinesis consumer is the config file for this code runner service. This service has no references to log4net and will not start when I put the log4net config info in its config file.

[andyg75]

I tried modifying the configurator to use the full path to the config file

System.IO.FileInfo log4netName = new System.IO.FileInfo(@"C:\path...\Log4Net.config"); XmlConfigurator.Configure(log4netName);

no dice.

[andyg75]

Just realized that I have been doing all of this configuration and such on our code--which is not using log4net. I need to try checking the config on our copy of your library and possibly recompiling it if I find anything that looks fishy.

[theburningmonk]

hey, sorry I lost track of these for a while, did you figure out the issue?

[andyg75]

No worries Not yet but I think I might be on the right track... I added this to your AssemblyInfo.fs: [assembly: log4net.Config.XmlConfigurator(Watch = true)] (had to remove greater than / less than signs for it to show up here)

and i added the log4net xmlconfig noted above to your app.config and built the reactoKinesix solution. i put the new dll and config file into the "packages" directory where our code is referencing it. rebuilt our code and ran a test... but... still no luck. no logging from your library in either the file that i configured or in the debug window.

[andyg75]

We got the reactokinesix binaries that we are using directly from github. I tried building locally to add in the additional config noted above but that didn't work... From what I remember early on it was logging to the output window when running the code in debug mode. It doesn't even do that any more... Is there anything we could have done in our application to mess up log4net functionality in your compiled code?

[theburningmonk]

Hey, I've been looking over the code and our set up and I don't see us doing anything special for logging. If it logs to the debug window then it should log to files all the same, since it's just log4net configuration.

Are there places where logging is missing? I'm happy to add some more logging or take a pull request if it means you can just use the nuget package.

The log4net configuration needs to be applied to the hosting application though, i.e. if I'm running a console app that kick starts an instance of the processor, then the log4net configs are applied in the console app project, including the XmlConfigurator attribute. Could that be the problem?

[andyg75]

thanks! i have tried configuring everything to death. it's not logging anything to the debug window or text file. in my first post i detailed what we're doing in our application regarding log4net config.

[andyg75]

Found something interesting... when we try to Register the app, the CreateNew method is working fine but apparently all of the error levels are disabled.

[theburningmonk]

That's interesting, my code checks if a logger's debug and info is enabled before attempting to use them so if they're disabled somehow then makes sense that it doesn't log anything.

Any idea why they're disabled?

On Tue, Feb 3, 2015 at 7:27 PM, Andy Gerard notifications@github.com wrote:

Found something interesting... when we try to Register the app, the CreateNew method is working fine but apparently all of the error levels are disabled.

[image: kinesislogging] https://cloud.githubusercontent.com/assets/9850196/6027443/314da364-abb0-11e4-97d1-705fc4ea09c0.png

— Reply to this email directly or view it on GitHub https://github.com/theburningmonk/ReactoKinesiX/issues/51#issuecomment-72716994 .

[andyg75]

I tried grabbing a fresh copy of your source code, making some log4net config tweaks that I hoped would cause it to log, and recompiled it. Since then I haven’t been able to get anything working—even after having reverted back to your original pre-compiled dll. It isn’t handing over the shards to the consumer app being run from my desktop anymore, nor will it call our Process Records method. So I seem to have screwed things up on my end pretty thoroughly... At this point I don’t know that this logging disabled thing is a real clue, given how I seem to have broken everything else. I’m going to try again today starting from step 1 to try to get the basic functionality working from my desktop again. Yes, I’m fairly new to this if you hadn’t guessed already. ;)

Thanks, Andy

From: Yan Cui [mailto:notifications@github.com] Sent: Tuesday, February 03, 2015 4:47 PM To: theburningmonk/ReactoKinesiX Cc: Andy Gerard Subject: Re: [ReactoKinesiX] Kinesis client app not logging+ (#51)

That's interesting, my code checks if a logger's debug and info is enabled before attempting to use them so if they're disabled somehow then makes sense that it doesn't log anything.

Any idea why they're disabled?

On Tue, Feb 3, 2015 at 7:27 PM, Andy Gerard notifications@github.com<mailto:notifications@github.com> wrote:

Found something interesting... when we try to Register the app, the CreateNew method is working fine but apparently all of the error levels are disabled.

[image: kinesislogging] https://cloud.githubusercontent.com/assets/9850196/6027443/314da364-abb0-11e4-97d1-705fc4ea09c0.png

— Reply to this email directly or view it on GitHub https://github.com/theburningmonk/ReactoKinesiX/issues/51#issuecomment-72716994 .

— Reply to this email directly or view it on GitHubhttps://github.com/theburningmonk/ReactoKinesiX/issues/51#issuecomment-72741935.

This email message, together with any attachments, contains information of Eliza Corporation which may be confidential, proprietary and/or legally privileged. It is intended solely for the use of the individual or entity named on this message. If you are not the intended recipient, and have received this message in error, please notify the sender immediately by reply e-mail and then delete it from your system.

[andyg75]

I found that while it is not doing any processing of records from my desktop, it is indeed handing over the shards. It’s simply using a differently named Kinesis State Dynamo table. But it’s clearly not calling our process records method regardless of how much data is in the stream. I have your source code built locally and am referencing the .dll I compiled from it so I can step through everything now and should be able to figure out 1) why it’s not logging and 2) why it’s not processing.

From: Andy Gerard Sent: Wednesday, February 04, 2015 9:15 AM To: 'theburningmonk/ReactoKinesiX' Subject: RE: [ReactoKinesiX] Kinesis client app not logging+ (#51)

I tried grabbing a fresh copy of your source code, making some log4net config tweaks that I hoped would cause it to log, and recompiled it. Since then I haven’t been able to get anything working—even after having reverted back to your original pre-compiled dll. It isn’t handing over the shards to the consumer app being run from my desktop anymore, nor will it call our Process Records method. So I seem to have screwed things up on my end pretty thoroughly... At this point I don’t know that this logging disabled thing is a real clue, given how I seem to have broken everything else. I’m going to try again today starting from step 1 to try to get the basic functionality working from my desktop again. Yes, I’m fairly new to this if you hadn’t guessed already. ;)

Thanks, Andy

From: Yan Cui [mailto:notifications@github.com] Sent: Tuesday, February 03, 2015 4:47 PM To: theburningmonk/ReactoKinesiX Cc: Andy Gerard Subject: Re: [ReactoKinesiX] Kinesis client app not logging+ (#51)

That's interesting, my code checks if a logger's debug and info is enabled before attempting to use them so if they're disabled somehow then makes sense that it doesn't log anything.

Any idea why they're disabled?

On Tue, Feb 3, 2015 at 7:27 PM, Andy Gerard notifications@github.com<mailto:notifications@github.com> wrote:

Found something interesting... when we try to Register the app, the CreateNew method is working fine but apparently all of the error levels are disabled.

[image: kinesislogging] https://cloud.githubusercontent.com/assets/9850196/6027443/314da364-abb0-11e4-97d1-705fc4ea09c0.png

— Reply to this email directly or view it on GitHub https://github.com/theburningmonk/ReactoKinesiX/issues/51#issuecomment-72716994 .

— Reply to this email directly or view it on GitHubhttps://github.com/theburningmonk/ReactoKinesiX/issues/51#issuecomment-72741935.

This email message, together with any attachments, contains information of Eliza Corporation which may be confidential, proprietary and/or legally privileged. It is intended solely for the use of the individual or entity named on this message. If you are not the intended recipient, and have received this message in error, please notify the sender immediately by reply e-mail and then delete it from your system.

[andyg75]

I have logging working now. In stepping through the code I found the location where the log4net.config file was being looked for and I set up my solution to place the file there. This is more than a little bit frustrating since I was pretty sure that was one of the first things I tried... but... in any case I do believe I have wasted enough of your time on this and I'll close out the issue this afternoon.

[andyg75]

Ok scratch that. I have log4net reading my config file now and your code now has logging enabled for all levels set to true. However, when I get to a line in your code that is supposed to do some logging I get nothing in the debug output window and nothing is written to text as I have configured in my log4net.config file.

[andyg75]

For instance, this executes but nothing is logged:

let = Observable.FromAsync(DynamoDBUtils.awaitStateTableReady dynamoDB tableName) .Subscribe(fun -> initializedEvent.Trigger(this, new EventArgs()) logDebug "State table [{0}] is ready, initializing shard processors..." [| tableName |] Async.Start(checkStreamChanges, cts.Token))

[theburningmonk]

So when you debug your program to the logDebug function, can you see that DebugEnabled is true, and that you have a file logger configured at the root level?

Based on configuration, log4net's file logger can also buffer log messages and flush them periodically so it might not appear right away but the lag should be in seconds max.

On Wed, Feb 4, 2015 at 9:10 PM, Andy Gerard notifications@github.com wrote:

For instance, this executes but nothing is logged:

let = Observable.FromAsync(DynamoDBUtils.awaitStateTableReady dynamoDB tableName) .Subscribe(fun -> initializedEvent.Trigger(this, new EventArgs()) logDebug "State table [{0}] is ready, initializing shard processors..." [| tableName |] Async.Start(checkStreamChanges, cts.Token))

— Reply to this email directly or view it on GitHub https://github.com/theburningmonk/ReactoKinesiX/issues/51#issuecomment-72940068 .

[andyg75]

Yes, DebugEnabled is true. Also, I see the RollingFileAppender configured and when I drill down it shows the location that I have set up in the config file as to where it should be writing. I've given it several minutes but nothing shows up in the log file or output window. My config file for log4net has <add key="log4net.Internal.Debug" value="true"/>, so I would expect any errors in log4net itself to be displayed as well.

I also added the following to Client.fs in the CreateNew method just before the "new ReactoKinesixApp"

let loggerName  = sprintf "ReactoKinesixShardProcessor[Stream:%O, Worker:%O, Shard:%O]" streamName workerId "shardId"

let logger      = LogManager.GetLogger(loggerName)

let logDebug    = logDebug logger

logger.Debug("Testing")

it steps through all of this with no errors but simply doesn't output anything...

[andyg75]

I am getting a whole bunch of "first chance" exceptions when I attempt to start the consumer app:

A first chance exception of type 'Amazon.Runtime.Internal.HttpErrorResponseException' occurred in mscorlib.dll A first chance exception of type 'Amazon.DynamoDBv2.Model.ConditionalCheckFailedException' occurred in AWSSDK.dll

[theburningmonk]

Can you share your log4net config?

On Thu, Feb 5, 2015 at 2:06 PM, Andy Gerard notifications@github.com wrote:

Yes, DebugEnabled is true. Also, I see the RollingFileAppender configured and when I drill down it shows the location that I have set up in the config file as to where it should be writing. I've given it several minutes but nothing shows up in the log file or output window. My config file for log4net has , so I would expect any errors in log4net itself to be displayed as well.

I also added the following to Client.fs in the CreateNew method just before the "new ReactoKinesixApp"

let loggerName = sprintf "ReactoKinesixShardProcessor[Stream:%O, Worker:%O, Shard:%O]" streamName workerId "shardId"

let logger = LogManager.GetLogger(loggerName)

let logDebug = logDebug logger

logger.Debug("Testing")

it steps through all of this with no errors but simply doesn't output anything...

— Reply to this email directly or view it on GitHub https://github.com/theburningmonk/ReactoKinesiX/issues/51#issuecomment-73050807 .

[andyg75]

The one in the first message in this thread has been tweaked a little bit. Here is the current version.

<?xml version="1.0" encoding="utf-8"?>
<configuration>
  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler,Log4net"/>
  </configSections>
  <appsettings>
    <add key="log4net.Internal.Debug" value="true"/>
  </appsettings>
  <log4net>
    <appender name="LogFileAppender" type="log4net.Appender.RollingFileAppender">
      <file value="C:\logfiles\%Y-%m\%Y%m%d\kinesis.log" />
      <appendToFile value="true" />
      <rollingStyle value="Size" />
      <maxSizeRollBackups value="10" />
      <maximumFileSize value="100MB" />
      <staticLogFileName value="true" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%-5p%d{yyyy-MM-dd hh:mm:ss} – %m%n" />
      </layout>
    </appender>
    <root>
      <level value="DEBUG" />
      <appender-ref ref="LogFileAppender" />
    </root>
  </log4net>
</configuration>

[andyg75]

Ok, I've got it working now and I think I know what the problem was.

<file value="C:\logfiles\%Y-%m\%Y%m%d\kinesis.log" />

It doesn't like the dynamic dated folder name thing. I changed it to "c:\logfiles\kinesis.log" and it wrote a file containing my "testing" message and is now logging all sorts of good stuff.

i will figure out how to get the dated folder thing working, but this does appear to be fixed for now and was entirely a "configure log4net properly" thing.