Message being truncated(?) when using the RollingLogFileAppender through ParallelForwardingAppender

[torndar]

When I log directly to the RollingLogFileAppender I get output like this:

INFO  2015-04-30 15:24:48,789  1263(ms) INTERNAL.APP.60                Run                - APP Started
DEBUG 2015-04-30 15:24:49,039  1513(ms) INTERNAL.APP.60                RunDailyJobs       - Looking for Daily jobs that are ready to be run.
DEBUG 2015-04-30 15:24:49,413  1887(ms) INTERNAL.APP.60                RunJobs            - Running [0] jobs
DEBUG 2015-04-30 15:24:49,413  1887(ms) INTERNAL.APP.60                RunWeeklyJobs      - Looking for Weekly jobs that are ready to be run.
DEBUG 2015-04-30 15:24:49,429  1903(ms) INTERNAL.APP.60                RunJobs            - Running [0] jobs
...
INFO  2015-04-30 15:24:49,554  2028(ms) INTERNAL.APP.60                Run                - APP Completed

But when I log through ParallelForwardingAppender I seem to lose the last portion of each message. It seems to lose the %-18.18M - %message %newline portion of the conversion pattern (including the newline so all the below really does show up as one line).

INFO  2015-04-30 15:27:10,174  1435(ms) INTERNAL.APP.60                DEBUG 2015-04-30 15:27:10,283  1544(ms) INTERNAL.APP.60                DEBUG 2015-04-30 15:27:10,579  1840(ms) INTERNAL.APP.60                DEBUG 2015-04-30 15:27:10,595  1856(ms) INTERNAL.APP.60                DEBUG 2015-04-30 15:27:10,611  1872(ms) INTERNAL.APP.60                DEBUG 2015-04-30 15:27:10,611  1872(ms) INTERNAL.APP.60                DEBUG 2015-04-30 15:27:10,626  1887(ms) INTERNAL.APP.60                DEBUG 2015-04-30 15:27:10,626  1887(ms) INTERNAL.APP.60                DEBUG 2015-04-30 15:27:10,626  1887(ms) INTERNAL.APP.60                INFO  2015-04-30 15:27:10,626  1887(ms) FileMovement.APPFileMovement   DEBUG 2015-04-30 15:27:10,673  1934(ms) FileMovement.APPFileMovement   DEBUG 2015-04-30 15:27:10,704  1965(ms) FileMovement.APPFileMovement   DEBUG 2015-04-30 15:27:10,720  1981(ms) FileMovement.APPFileMovement   DEBUG 2015-04-30 15:27:10,735  1996(ms) FileMovement.APPFileMovement   DEBUG 2015-04-30 15:27:10,751  2012(ms) FileMovement.APPFileMovement   DEBUG 2015-04-30 15:27:10,751  2012(ms) FileMovement.APPFileMovement   INFO  2015-04-30 15:27:10,751  2012(ms) INTERNAL.APP.60

The appender configuration is:

<appender name="RollingLogFileAppender" type="log4net.Appender.RollingFileAppender">
  <file type="log4net.Util.PatternString" value="D:\\APP2012\\Logs\\APP.%property{InstanceId}.txt" />
  <appendToFile value="true" />
  <rollingStyle value="Size" />
  <maxSizeRollBackups value="10" />
  <maximumFileSize value="10MB" />
  <staticLogFileName value="true" />
  <layout type="log4net.Layout.PatternLayout">
    <conversionPattern value="%-5level %date{ISO8601} %5timestamp(ms) %-30.30logger %-18.18M - %message %newline" />
  </layout>
</appender>

[cjbhaines]

@rcollette any ideas on this one before I dig into it?

[rcollette]

Not off the top of my head. I will not have time to look at it at until at least this weekend.

[coryflucas]

This is due to the Fix property being set to FixFlags.Partial in AsyncForwardingAppenderBase. Partial does not include FixFlags.LocationInfo which is what is used for the caller info fields such as method which caused the problem described. This is the same issue as #15. Setting the property to FixFlags.All or FixFlags.Partial | FixFlags.LocationInfo seems to fix the problem. Unfortunately I don't seem to be able to set it via XML config.

[cjbhaines]

Hi @coryflucas, thanks for the information! We should look at providing a way to set this from the config. If I remember correctly, isn't there a perfoamnce hit for using FixFlags.All?

[coryflucas]

Yes, there is a performance hit because the LocationInfo items are using reflection I believe. An option to override the default would give the user the option to allow the fields to be passed if they were ok with the performance hit.