[
https://issues.apache.org/jira/browse/JAMES-3251?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17144643#comment-17144643
]
David Leangen commented on JAMES-3251:
--------------------------------------
h1. Breaking down the log output into actionable chunks
Note that this refers to the *Basic* log output only. As stated in the
description of this issue, we may want to re-introduce some of the entries into
a separate diagnostic output later.
(I have moved around the order of the log entries in my crude attempt at
categorizing them.)
h2. Logging info about logging
{noformat}
james_1 | 14:02:36,033 |-INFO in ch.qos.logback.classic.LoggerContext[default]
- Could NOT find resource
[/opt/apache-james/james-basic-server/conf/logback.xml]
james_1 | 14:02:36,034 |-INFO in ch.qos.logback.classic.LoggerContext[default]
- Could NOT find resource [logback-test.xml]
james_1 | 14:02:36,035 |-INFO in ch.qos.logback.classic.LoggerContext[default]
- Could NOT find resource [logback.groovy]
james_1 | 14:02:36,038 |-INFO in ch.qos.logback.classic.LoggerContext[default]
- Found resource [logback.xml] at
[jar:file:/opt/apache-james/james-basic-server/lib/james-server-jpa-guice-3.6.0-SNAPSHOT.jar!/logback.xml]
james_1 | 14:02:36,065 |-INFO in
ch.qos.logback.core.joran.spi.ConfigurationWatchList@3a52dba3 - URL
[jar:file:/opt/apache-james/james-basic-server/lib/james-server-jpa-guice-3.6.0-SNAPSHOT.jar!/logback.xml]
is not of type file
james_1 | 14:02:36,320 |-INFO in
ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not
set
james_1 | 14:02:36,322 |-INFO in
ch.qos.logback.classic.joran.action.LoggerContextListenerAction - Adding
LoggerContextListener of type
[ch.qos.logback.classic.jul.LevelChangePropagator] to the object stack
james_1 | 14:02:36,379 |-INFO in
ch.qos.logback.classic.jul.LevelChangePropagator@2a5c8d3f - Propagating DEBUG
level on Logger[ROOT] onto the JUL framework
james_1 | 14:02:36,380 |-INFO in
ch.qos.logback.classic.joran.action.LoggerContextListenerAction - Starting
LoggerContextListener
james_1 | 14:02:36,380 |-INFO in
ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender
of type [ch.qos.logback.core.ConsoleAppender]
james_1 | 14:02:36,386 |-INFO in
ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [CONSOLE]
james_1 | 14:02:36,389 |-INFO in
ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default
type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder]
property
james_1 | 14:02:36,396 |-WARN in
ch.qos.logback.classic.encoder.PatternLayoutEncoder@752325ad - As of version
1.2.0 "immediateFlush" property should be set within the enclosing Appender.
james_1 | 14:02:36,396 |-WARN in
ch.qos.logback.classic.encoder.PatternLayoutEncoder@752325ad - Please move
"immediateFlush" property into the enclosing appender.
james_1 | 14:02:36,512 |-WARN in
ch.qos.logback.classic.encoder.PatternLayoutEncoder@752325ad - Setting the
"immediateFlush" property of the enclosing appender to false
james_1 | 14:02:36,513 |-INFO in
ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT
logger to WARN
james_1 | 14:02:36,513 |-INFO in
ch.qos.logback.classic.jul.LevelChangePropagator@2a5c8d3f - Propagating WARN
level on Logger[ROOT] onto the JUL framework
james_1 | 14:02:36,513 |-INFO in
ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named
[CONSOLE] to Logger[ROOT]
james_1 | 14:02:36,514 |-INFO in
ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger
[org.apache.james] to INFO
james_1 | 14:02:36,514 |-INFO in
ch.qos.logback.classic.jul.LevelChangePropagator@2a5c8d3f - Propagating INFO
level on Logger[org.apache.james] onto the JUL framework
james_1 | 14:02:36,515 |-INFO in
ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
james_1 | 14:02:36,520 |-INFO in
ch.qos.logback.classic.joran.JoranConfigurator@279fedbd - Registering current
configuration as safe fallback point
{noformat}
It looks to me like anything in the ch.qos.logback.classic space (and maybe
even higher) can be safely omitted from the Basic log output.
h2. Logging info about configuration
I'm not 100% sure what do to about this one, but I'll go ahead and eliminate
from the Basic log output for now.
{noformat}
james_1 |
james_1 | 14:02:36.576 [INFO ] o.a.j.CONFIGURATION - Loading configuration
Basic{configurationPath=ConfigurationPath{value=file://conf/},
directories=JamesServerResourceLoader{rootDirectory=/opt/apache-james/james-basic-server,
varDirectory=/opt/apache-james/james-basic-server/var/,
confDirectory=/opt/apache-james/james-basic-server/conf/}}
{noformat}
h2. StartUpChecks
Not sure about this one. The general message that "the system is up" is great
for the Operator, but the message here seems to be very detailed and technical,
i.e. Developer-oriented and not Operator-oriented.
I think I will keep it, and address the message in point #2 as per this issue's
description.
{noformat}
james_1 | 14:02:39.035 [INFO ] o.a.j.StartUpChecksPerformer - StartUpChecks
all succeeded
{noformat}
h2. Missing configuration files
There is a large chunk of logging output that relates to configuration files.
None of these are desirable, I think, so I will remove them from the Basic log
output.
{noformat}
james_1 | 14:02:39.270 [INFO ] o.a.j.CONFIGURATION - Load configuration file
/opt/apache-james/james-basic-server/conf/healthcheck.properties
james_1 | 14:02:39.273 [WARN ] o.a.j.m.PeriodicalHealthChecksModule - Could
not find healthcheck configuration file, using default configuration
james_1 | 14:02:39.984 [INFO ] o.a.j.CONFIGURATION - Load configuration file
/opt/apache-james/james-basic-server/conf/extensions.properties
james_1 | 14:02:40.045 [INFO ] o.a.j.u.ExtensionModule - No
extensions.properties configuration found. No additional Guice module will be
used for instantiating extensions.
james_1 | 14:02:40.077 [WARN ] o.a.j.s.c.c.FileConfigurationProvider - Unable
to locate configuration file mailrepositorystore.xml, assuming empty
configuration
james_1 | 14:02:40.087 [WARN ] o.a.j.m.s.MailStoreRepositoryModule - Empty
MailRepository store configuration supplied. Defaulting to default
configuration for this product
james_1 | 14:02:41.069 [INFO ] o.a.j.CONFIGURATION - Load configuration file
/opt/apache-james/james-basic-server/conf/elasticsearch.properties
james_1 | 14:02:41.070 [INFO ] o.a.j.m.s.ElasticSearchMetricReporterModule -
Can not locate elasticsearch configuration
james_1 | 14:02:41.074 [WARN ] o.a.j.s.c.c.FileConfigurationProvider - Unable
to locate configuration file domainlist.xml, assuming empty configuration
james_1 | 14:02:44.239 [WARN ] o.a.j.s.c.c.FileConfigurationProvider - Unable
to locate configuration file listeners.xml, assuming empty configuration
james_1 | 14:02:44.423 [INFO ] o.a.j.CONFIGURATION - Load configuration file
/opt/apache-james/james-basic-server/conf/webadmin.properties
james_1 | 14:02:44.424 [INFO ] o.a.j.m.s.WebAdminServerModule - No
webadmin.properties file. Disabling WebAdmin interface.
james_1 | 14:02:45.660 [INFO ] o.a.j.CONFIGURATION - Load configuration file
/opt/apache-james/james-basic-server/conf/webadmin.properties
james_1 | 14:02:45.673 [INFO ] o.a.j.CONFIGURATION - Load configuration file
/opt/apache-james/james-basic-server/conf/jmx.properties
james_1 | 14:02:45.674 [WARN ] o.a.j.m.s.JMXServerModule - Could not locate
configuration file for JMX. Defaults to rmi://127.0.0.1:9999
james_1 | 14:02:45.702 [WARN ] o.a.j.s.c.c.FileConfigurationProvider - Unable
to locate configuration file dnsservice.xml, assuming empty configuration
james_1 | 14:02:46.212 [WARN ] o.a.j.s.c.c.FileConfigurationProvider - Unable
to locate configuration file usersrepository.xml, assuming empty configuration
james_1 | 14:02:46.215 [WARN ] o.a.j.s.c.c.FileConfigurationProvider - Unable
to locate configuration file recipientrewritetable.xml, assuming empty
configuration
james_1 | 14:02:46.216 [WARN ] o.a.j.s.c.c.FileConfigurationProvider - Unable
to locate configuration file mailetcontainer.xml, assuming empty configuration
james_1 | 14:02:46.218 [WARN ] o.a.j.m.s.CamelMailetContainerModule - Could
not locate configuration for Mailet context. Assuming empty configuration for
this component.
james_1 | 14:02:46.398 [WARN ] o.a.j.s.c.c.FileConfigurationProvider - Unable
to locate configuration file mailetcontainer.xml, assuming empty configuration
james_1 | 14:02:46.398 [WARN ] o.a.j.m.s.CamelMailetContainerModule - Could
not load configuration for Processors. Fallback to default.
james_1 | 14:02:47.453 [WARN ] o.a.j.s.c.c.FileConfigurationProvider - Unable
to locate configuration file imapserver.xml, assuming empty configuration
james_1 | 14:02:47.456 [INFO ] o.a.j.s.c.c.FileConfigurationProvider - Unable
to locate configuration file lmtpserver.xml, assuming empty configuration
james_1 | 14:02:47.457 [INFO ] o.a.j.s.c.c.FileConfigurationProvider - Unable
to locate configuration file managesieveserver.xml, assuming empty configuration
james_1 | 14:02:47.496 [INFO ] o.a.j.p.l.n.AbstractConfigurableAsyncServer -
POP3 Service disabled by configuration
james_1 | 14:02:47.497 [WARN ] o.a.j.s.c.c.FileConfigurationProvider - Unable
to locate configuration file smtpserver.xml, assuming empty configuration
james_1 | 14:02:47.300 [WARN ] o.a.j.s.c.c.FileConfigurationProvider - Unable
to locate configuration file mailetcontainer.xml, assuming empty configuration
{noformat}
h2. BrokerService
Will probably file a separate issue for this one:
{noformat}
james_1 | 14:02:40.544 [WARN ] o.a.a.b.BrokerService - Memory Usage for the
Broker (1024mb) is more than the maximum available for the JVM: 986 mb -
resetting to 70% of maximum available: 690 mb
james_1 | 14:02:40.892 [WARN ] o.a.a.b.BrokerService - Store limit is 102400
mb (current store usage is 0 mb). The data directory:
/opt/apache-james/james-basic-server/var/store/activemq/brokers/KahaDB only has
55732 mb of usable space. - resetting to maximum available disk space: 55732 mb
{noformat}
h2. ActiveMQ
Not needed for the Basic Operator.
{noformat}
james_1 | 14:02:40.923 [INFO ] o.a.j.q.a.EmbeddedActiveMQ - Started embedded
activeMq
{noformat}
h2. JPA / database
Not needed for the Basic Operator.
{noformat}
james_1 | 1200 Global INFO [main] openjpa.Runtime - Starting OpenJPA 3.1.0
james_1 | 1285 Global INFO [main] openjpa.jdbc.JDBC - Using dictionary
class "org.apache.openjpa.jdbc.sql.DerbyDictionary".
james_1 | 2660 Global INFO [main] openjpa.jdbc.JDBC - Connected to Apache
Derby version 10.10 using JDBC driver Apache Derby Embedded JDBC Driver version
10.14.2.0 - (1828579).
james_1 | 48 Global WARN [main] openjpa.Runtime - Could not create the optional
validation provider. Reason returned: "A default ValidatorFactory could not be
created."
james_1 | 14:02:39.287 [INFO ] o.a.j.CONFIGURATION - Load configuration file
/opt/apache-james/james-basic-server/conf/james-database.properties
{noformat}
h2. DNS
Not sure about this one. This is something that is likely within the realm of
the Basic Operator. I will leave this for now and address as per point #2 in
this issue's description.
{noformat}
james_1 | 14:02:45.702 [INFO ] o.a.j.d.d.DNSJavaService - Autodiscovery is
enabled - trying to discover your system's DNS Servers
james_1 | 14:02:45.712 [INFO ] o.a.j.d.d.DNSJavaService - Adding
autodiscovered server 127.0.0.11
james_1 | 14:02:45.716 [INFO ] o.a.j.d.d.DNSJavaService - DNS Server is:
127.0.0.11
james_1 | 14:02:45.733 [INFO ] o.a.j.d.d.DNSJavaService - Registered cache,
resolver and search paths as DNSJava defaults
{noformat}
h2. MemoryMailRepositoryStore
I fail to see how this could be useful for the Basic Operator, so will remove.
{noformat}
james_1 | 14:02:45.798 [INFO ] o.a.j.m.m.MemoryMailRepositoryStore -
JamesMailStore init...
org.apache.james.mailrepository.memory.MemoryMailRepositoryStore@1b26fac2
james_1 | 14:02:45.800 [INFO ] o.a.j.d.l.AbstractDomainList - Set autodetect
to: false
james_1 | 14:02:45.801 [INFO ] o.a.j.d.l.AbstractDomainList - Set autodetectIP
to: false
{noformat}
h2. Mailets and Extensions
In the context of the Basic Server, these should all be removed.
Looks like the space o.a.j.m.l.AbstractStateMailetProcessor is a good candidate
for removal.
{noformat}
james_1 | 14:02:46.675 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor -
Matcher All instantiated.
james_1 | 14:02:46.684 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor - Mailet
PostmasterAlias instantiated.
james_1 | 14:02:46.687 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor -
Matcher RelayLimit=30 instantiated.
james_1 | 14:02:46.691 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor - Mailet
Null instantiated.
james_1 | 14:02:46.692 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor -
Matcher All instantiated.
james_1 | 14:02:46.696 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor - Mailet
ToProcessor instantiated.
james_1 | 14:02:46.948 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor -
Matcher All instantiated.
james_1 | 14:02:46.965 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor - Mailet
Bounce instantiated.
james_1 | 14:02:46.966 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor -
Matcher All instantiated.
james_1 | 14:02:46.968 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor - Mailet
Null instantiated.
james_1 | 14:02:46.985 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor -
Matcher SMTPAuthSuccessful instantiated.
james_1 | 14:02:46.994 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor - Mailet
SetMimeHeader instantiated.
james_1 | 14:02:46.995 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor -
Matcher All instantiated.
james_1 | 14:02:47.002 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor - Mailet
RemoveMimeHeader instantiated.
james_1 | 14:02:47.003 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor -
Matcher All instantiated.
james_1 | 14:02:47.019 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor - Mailet
RecipientRewriteTable instantiated.
james_1 | 14:02:47.023 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor -
Matcher RecipientIsLocal instantiated.
james_1 | 14:02:47.039 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor - Mailet
LocalDelivery instantiated.
james_1 | 14:02:47.045 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor -
Matcher HostIsLocal instantiated.
james_1 | 14:02:47.050 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor - Mailet
ToProcessor instantiated.
james_1 | 14:02:47.051 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor -
Matcher SMTPAuthSuccessful instantiated.
james_1 | 14:02:47.168 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor - Mailet
RemoteDelivery instantiated.
james_1 | 14:02:47.169 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor -
Matcher All instantiated.
james_1 | 14:02:47.182 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor - Mailet
ToProcessor instantiated.
james_1 | 14:02:47.216 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor -
Matcher All instantiated.
james_1 | 14:02:47.217 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor - Mailet
Null instantiated.
james_1 | 14:02:47.226 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor -
Matcher All instantiated.
james_1 | 14:02:47.230 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor - Mailet
Bounce instantiated.
james_1 | 14:02:47.231 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor -
Matcher All instantiated.
james_1 | 14:02:47.232 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor - Mailet
Null instantiated.
james_1 | 14:02:47.254 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor -
Matcher All instantiated.
james_1 | 14:02:47.256 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor - Mailet
Bounce instantiated.
james_1 | 14:02:47.257 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor -
Matcher All instantiated.
james_1 | 14:02:47.260 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor - Mailet
Null instantiated.
james_1 | 14:02:47.271 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor -
Matcher All instantiated.
james_1 | 14:02:47.285 [INFO ] o.a.j.m.l.AbstractStateMailetProcessor - Mailet
DSNBounce instantiated.
{noformat}
h2. Various
Not sure what these are. Will remove.
{noformat}
james_1 | 14:02:47.307 [WARN ] o.a.j.m.s.CamelMailetContainerModule - Could
not locate configuration for James Spooler. Assuming empty configuration for
this component.
james_1 | 14:02:47.316 [INFO ] o.a.j.m.i.JamesMailSpooler - init...
james_1 | 14:02:47.316 [INFO ] o.a.j.m.i.JamesMailSpooler - Concurrency level
is 100
james_1 | 14:02:47.320 [INFO ] o.a.j.m.i.JamesMailSpooler - Spooler started
james_1 | 14:02:47.359 [INFO ] o.a.j.r.f.AbstractFileRepository - Init
org.apache.james.repository.file.FilePersistentObjectRepository Store
james_1 | 14:02:47.373 [INFO ] o.a.j.r.f.AbstractFileRepository -
org.apache.james.repository.file.FilePersistentObjectRepository opened in
/opt/apache-james/james-basic-server/var/mail/error
james_1 | 14:02:47.375 [INFO ] o.a.j.r.f.AbstractFileRepository - Init
org.apache.james.repository.file.FilePersistentStreamRepository Store
james_1 | 14:02:47.376 [INFO ] o.a.j.r.f.AbstractFileRepository -
org.apache.james.repository.file.FilePersistentStreamRepository opened in
/opt/apache-james/james-basic-server/var/mail/error
james_1 | 14:02:47.447 [INFO ] o.a.j.m.m.MailboxListenersLoaderImpl - Loading
user registered mailbox listeners
{noformat}
h2. maxRetries
I recall that there is already an open issue about this one. Report back there.
{noformat}
james_1 | 14:02:47.085 [WARN ] o.a.j.t.m.r.d.DelaysAndMaxRetry - maxRetries is
larger than total number of attempts specified. Increasing last delayTime with
22 attempts
james_1 | 14:02:47.087 [WARN ] o.a.j.t.m.r.d.DelaysAndMaxRetry - Delay of 8
minutes 20 seconds is now attempted: 1 times
{noformat}
h2. Unknown (to me, anyway)
Don't know what this is about. Will probably file a separate issue.
{noformat}
james_1 | WARNING: An illegal reflective access operation has occurred
james_1 | WARNING: Illegal reflective access by
com.google.inject.internal.cglib.core.$ReflectUtils$1
(file:/opt/apache-james/james-basic-server/lib/guice-4.2.2.jar) to method
java.lang.ClassLoader.defineClass(java.lang.String,byte[],int,int,java.security.ProtectionDomain)
james_1 | WARNING: Please consider reporting this to the maintainers of
com.google.inject.internal.cglib.core.$ReflectUtils$1
james_1 | WARNING: Use --illegal-access=warn to enable warnings of further
illegal reflective access operations
james_1 | WARNING: All illegal access operations will be denied in a future
release
{noformat}
> Reduce INFO chatter for Basic Server
> ------------------------------------
>
> Key: JAMES-3251
> URL: https://issues.apache.org/jira/browse/JAMES-3251
> Project: James Server
> Issue Type: Sub-task
> Reporter: David Leangen
> Priority: Major
>
> In the context of the *Basic Server*, based on the principle that the
> Operator does not know (and does not need to know) the internals of the
> system:
> # Reduce the Operator's log output to the absolute minimum (in one way or
> another)
> # Ensure that any output is useful and actionable in the Basic context
> # Consider what to do with regard to diagnostic information that, in the
> case of a problem, would allow experienced James Developers to assist when
> necessary
> This issue focuses only on point #1 in the above list. Once that is
> completed, we should consider the other two points.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
---------------------------------------------------------------------
To unsubscribe, e-mail: server-dev-unsubscr...@james.apache.org
For additional commands, e-mail: server-dev-h...@james.apache.org
