log4j:WARN

[Jacques Le Roux]

Hi,

I'm not sure if we should worry but I sometimes see these log4j:WARN in the log

    log4j:WARN No appenders could be found for logger (freemarker.cache).
    log4j:WARN Please initialize the log4j system properly.
    log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.

I checked log4j2.xml and we define

         <Loggers>
             <logger name="org.apache" level="warn"/>
             <logger name="org.apache.ofbiz" level="all"/>
             <logger name="org.apache.ofbiz.base.converter.Converters" level="warn"/>
             <logger name="freemarker" level="warn"/>

             <Root level="all">
                 <AppenderRef ref="async"/>
             </Root>
         </Loggers>

So I don't see the reason. Maybe it's because it's loaded later?

Jacques
PS: below is a more complete log extract with a complete request context

2018-10-21 10:42:06,293 |jsse-nio-8443-exec-4 |ControlEventListener          |I| Creating session:  hidden sessionId by default.
2018-10-21 10:42:06,298 |jsse-nio-8443-exec-4 |ControlServlet                |T| [[[main(Domain:https://localhost)] Request Begun, encoding=[UTF-8]- total:0.0,since last(Begin):0.0]]
2018-10-21 10:42:06,302 |jsse-nio-8443-exec-4 |VisitHandler                  |I| Found visitorId [10000] in cookie
2018-10-21 10:42:06,317 |jsse-nio-8443-exec-4 |TransactionUtil               |W| No transaction in place, so not suspending.
2018-10-21 10:42:06,329 |jsse-nio-8443-exec-4 |SequenceUtil                  |I| Got bank of sequenced IDs for [Visit]; curSeqId=10100, maxSeqId=10200, bankSize=100
2018-10-21 10:42:06,367 |jsse-nio-8443-exec-4 |ConfigXMLReader               |I| controller loaded: 0.001s, 50 requests, 34 views in file:/C:/projectsASF/ofbiz/plugins/example/webapp/example/WEB-INF/controlle
r.xml
2018-10-21 10:42:06,385 |jsse-nio-8443-exec-4 |ConfigXMLReader               |I| controller loaded: 0.0s, 51 requests, 23 views in file:/C:/projectsASF/ofbiz/framework/common/webcommon/WEB-INF/common-controll
er.xml
2018-10-21 10:42:06,397 |jsse-nio-8443-exec-4 |ConfigXMLReader               |I| controller loaded: 0.0s, 0 requests, 0 views in file:/C:/projectsASF/ofbiz/framework/common/webcommon/WEB-INF/handlers-controll
er.xml
2018-10-21 10:42:06,409 |jsse-nio-8443-exec-4 |ConfigXMLReader               |I| controller loaded: 0.0s, 26 requests, 10 views in file:/C:/projectsASF/ofbiz/framework/common/webcommon/WEB-INF/portal-controll
er.xml
2018-10-21 10:42:06,444 |jsse-nio-8443-exec-4 |ConfigXMLReader               |I| controller loaded: 0.0s, 2 requests, 2 views in file:/C:/projectsASF/ofbiz/plugins/example/widget/example/ExampleCompoundWidget
s.xml
2018-10-21 10:42:06,447 |jsse-nio-8443-exec-4 |RequestHandler                |I| This is the first request in this visit. Hidden sessionId by default.
2018-10-21 10:42:06,454 |jsse-nio-8443-exec-4 |ExternalLoginKeysManager      |W| Could not find userLogin for external login key: EL00e7af53-b4b5-40d8-bec2-56ea21563066
2018-10-21 10:42:08,294 |jsse-nio-8443-exec-4 |UtilXml                       |E| XmlFileLoader: File file:/C:/projectsASF/ofbiz/themes/common-theme/widget/Theme.xml process error. Line: 169. Error message: cv
c-complex-type.2.4.d: Invalid content was found starting with element 'common-menus'. No child element is expected at this point.
2018-10-21 10:42:08,294 |jsse-nio-8443-exec-4 |UtilXml                       |E| XmlFileLoader: File file:/C:/projectsASF/ofbiz/themes/common-theme/widget/Theme.xml process error. Line: 171. Error message: cv
c-complex-type.2.4.a: Invalid content was found starting with element 'menu'. One of '{"http://ofbiz.apache.org/Widget-Theme":screen}' is expected.
2018-10-21 10:42:08,308 |jsse-nio-8443-exec-4 |UtilXml                       |E| XmlFileLoader: File file:/C:/projectsASF/ofbiz/themes/common-theme/widget/Theme.xml process error. Line: 169. Error message: cv
c-complex-type.2.4.d: Invalid content was found starting with element 'common-menus'. No child element is expected at this point.
2018-10-21 10:42:08,308 |jsse-nio-8443-exec-4 |UtilXml                       |E| XmlFileLoader: File file:/C:/projectsASF/ofbiz/themes/common-theme/widget/Theme.xml process error. Line: 171. Error message: cv
c-complex-type.2.4.a: Invalid content was found starting with element 'menu'. One of '{"http://ofbiz.apache.org/Widget-Theme":screen}' is expected.
2018-10-21 10:42:08,340 |jsse-nio-8443-exec-4 |RequestHandler                |I| Rendering View [login].  Hidden sessionId by default.
2018-10-21 10:42:08,355 |jsse-nio-8443-exec-4 |ServiceDispatcher             |T| Sync service [example/getUserPreferenceGroup] finished in [11] milliseconds
log4j:WARN No appenders could be found for logger (freemarker.cache).
log4j:WARN Please initialize the log4j system properly.
log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.
2018-10-21 10:42:09,020 |jsse-nio-8443-exec-4 |ScreenFactory                 |I| Got 28 screens in 0.439s from: file:/C:/projectsASF/ofbiz/framework/common/widget/CommonScreens.xml
2018-10-21 10:42:09,182 |jsse-nio-8443-exec-4 |FreeMarkerWorker              |I| loading properties: file:/C:/projectsASF/ofbiz/framework/webapp/config/freemarkerTransforms.properties
2018-10-21 10:42:09,183 |jsse-nio-8443-exec-4 |FreeMarkerWorker              |I| loading properties: file:/C:/projectsASF/ofbiz/framework/widget/config/freemarkerTransforms.properties
2018-10-21 10:42:09,184 |jsse-nio-8443-exec-4 |FreeMarkerWorker              |I| loading properties: file:/C:/projectsASF/ofbiz/applications/content/config/freemarkerTransforms.properties
2018-10-21 10:42:09,185 |jsse-nio-8443-exec-4 |FreeMarkerWorker              |I| loading properties: file:/C:/projectsASF/ofbiz/applications/product/config/freemarkerTransforms.properties
2018-10-21 10:42:09,368 |jsse-nio-8443-exec-4 |ScreenFactory                 |I| Got 27 screens in 0.202s from: file:/C:/projectsASF/ofbiz/themes/common-theme/widget/CommonScreens.xml
2018-10-21 10:42:09,376 |jsse-nio-8443-exec-4 |ScreenFactory                 |I| Got 8 screens in 0.007s from: file:/C:/projectsASF/ofbiz/plugins/example/widget/example/CommonScreens.xml
2018-10-21 10:42:09,724 |jsse-nio-8443-exec-4 |UtilProperties                |I| ResourceBundle CommonExtUiLabels (fr) created in 0.053s with 7 properties
2018-10-21 10:42:09,725 |jsse-nio-8443-exec-4 |PrimaryKeyFinder              |I| Returning null because found incomplete primary key in find: [GenericEntity:PartyNameView][partyId,null()]
2018-10-21 10:42:09,845 |jsse-nio-8443-exec-4 |ServiceDispatcher             |T| Sync service [example/getLastSystemInfoNote] finished in [18] milliseconds
2018-10-21 10:42:10,342 |jsse-nio-8443-exec-4 |ServerHitBin                  |I| Visit delegatorName=default, ServerHitBin delegatorName=default
2018-10-21 10:42:10,352 |jsse-nio-8443-exec-4 |ControlServlet                |T| [[[main(Domain:https://localhost)] Request Done- total:4.053,since last([main(Domain:http...):4.053]]

"Could not find userLogin for external login key: EL00e7af53-b4b5-40d8-bec2-56ea21563066" happened because I changed to another application after the session timed out, nothing abnormal.

[Jacques Le Roux]

Just found that it's related to FreeMarkerWorkerTests.java::renderTemplateFromString

Not sure why this happens then in the log


Le 21/10/2018 à 18:50, Jacques Le Roux a écrit :

> Hi,
>
> I'm not sure if we should worry but I sometimes see these log4j:WARN in the log
>
>    log4j:WARN No appenders could be found for logger (freemarker.cache).
>    log4j:WARN Please initialize the log4j system properly.
>    log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.
>
> I checked log4j2.xml and we define
>
>         <Loggers>
>             <logger name="org.apache" level="warn"/>
>             <logger name="org.apache.ofbiz" level="all"/>
>             <logger name="org.apache.ofbiz.base.converter.Converters" level="warn"/>
>             <logger name="freemarker" level="warn"/>
>
>             <Root level="all">
>                 <AppenderRef ref="async"/>
>             </Root>
>         </Loggers>
>
> So I don't see the reason. Maybe it's because it's loaded later?
>
> Jacques
> PS: below is a more complete log extract with a complete request context
>
> 2018-10-21 10:42:06,293 |jsse-nio-8443-exec-4 |ControlEventListener          |I| Creating session:  hidden sessionId by default.
> 2018-10-21 10:42:06,298 |jsse-nio-8443-exec-4 |ControlServlet                |T| [[[main(Domain:https://localhost)] Request Begun, encoding=[UTF-8]-
> total:0.0,since last(Begin):0.0]]
> 2018-10-21 10:42:06,302 |jsse-nio-8443-exec-4 |VisitHandler                  |I| Found visitorId [10000] in cookie
> 2018-10-21 10:42:06,317 |jsse-nio-8443-exec-4 |TransactionUtil               |W| No transaction in place, so not suspending.
> 2018-10-21 10:42:06,329 |jsse-nio-8443-exec-4 |SequenceUtil                  |I| Got bank of sequenced IDs for [Visit]; curSeqId=10100,
> maxSeqId=10200, bankSize=100
> 2018-10-21 10:42:06,367 |jsse-nio-8443-exec-4 |ConfigXMLReader               |I| controller loaded: 0.001s, 50 requests, 34 views in
> file:/C:/projectsASF/ofbiz/plugins/example/webapp/example/WEB-INF/controlle
> r.xml
> 2018-10-21 10:42:06,385 |jsse-nio-8443-exec-4 |ConfigXMLReader               |I| controller loaded: 0.0s, 51 requests, 23 views in
> file:/C:/projectsASF/ofbiz/framework/common/webcommon/WEB-INF/common-controll
> er.xml
> 2018-10-21 10:42:06,397 |jsse-nio-8443-exec-4 |ConfigXMLReader               |I| controller loaded: 0.0s, 0 requests, 0 views in
> file:/C:/projectsASF/ofbiz/framework/common/webcommon/WEB-INF/handlers-controll
> er.xml
> 2018-10-21 10:42:06,409 |jsse-nio-8443-exec-4 |ConfigXMLReader               |I| controller loaded: 0.0s, 26 requests, 10 views in
> file:/C:/projectsASF/ofbiz/framework/common/webcommon/WEB-INF/portal-controll
> er.xml
> 2018-10-21 10:42:06,444 |jsse-nio-8443-exec-4 |ConfigXMLReader               |I| controller loaded: 0.0s, 2 requests, 2 views in
> file:/C:/projectsASF/ofbiz/plugins/example/widget/example/ExampleCompoundWidget
> s.xml
> 2018-10-21 10:42:06,447 |jsse-nio-8443-exec-4 |RequestHandler                |I| This is the first request in this visit. Hidden sessionId by default.
> 2018-10-21 10:42:06,454 |jsse-nio-8443-exec-4 |ExternalLoginKeysManager      |W| Could not find userLogin for external login key:
> EL00e7af53-b4b5-40d8-bec2-56ea21563066
> 2018-10-21 10:42:08,294 |jsse-nio-8443-exec-4 |UtilXml                       |E| XmlFileLoader: File
> file:/C:/projectsASF/ofbiz/themes/common-theme/widget/Theme.xml process error. Line: 169. Error message: cv
> c-complex-type.2.4.d: Invalid content was found starting with element 'common-menus'. No child element is expected at this point.
> 2018-10-21 10:42:08,294 |jsse-nio-8443-exec-4 |UtilXml                       |E| XmlFileLoader: File
> file:/C:/projectsASF/ofbiz/themes/common-theme/widget/Theme.xml process error. Line: 171. Error message: cv
> c-complex-type.2.4.a: Invalid content was found starting with element 'menu'. One of '{"http://ofbiz.apache.org/Widget-Theme":screen}' is expected.
> 2018-10-21 10:42:08,308 |jsse-nio-8443-exec-4 |UtilXml                       |E| XmlFileLoader: File
> file:/C:/projectsASF/ofbiz/themes/common-theme/widget/Theme.xml process error. Line: 169. Error message: cv
> c-complex-type.2.4.d: Invalid content was found starting with element 'common-menus'. No child element is expected at this point.
> 2018-10-21 10:42:08,308 |jsse-nio-8443-exec-4 |UtilXml                       |E| XmlFileLoader: File
> file:/C:/projectsASF/ofbiz/themes/common-theme/widget/Theme.xml process error. Line: 171. Error message: cv
> c-complex-type.2.4.a: Invalid content was found starting with element 'menu'. One of '{"http://ofbiz.apache.org/Widget-Theme":screen}' is expected.
> 2018-10-21 10:42:08,340 |jsse-nio-8443-exec-4 |RequestHandler                |I| Rendering View [login].  Hidden sessionId by default.
> 2018-10-21 10:42:08,355 |jsse-nio-8443-exec-4 |ServiceDispatcher             |T| Sync service [example/getUserPreferenceGroup] finished in [11]
> milliseconds
> log4j:WARN No appenders could be found for logger (freemarker.cache).
> log4j:WARN Please initialize the log4j system properly.
> log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.
> 2018-10-21 10:42:09,020 |jsse-nio-8443-exec-4 |ScreenFactory                 |I| Got 28 screens in 0.439s from:
> file:/C:/projectsASF/ofbiz/framework/common/widget/CommonScreens.xml
> 2018-10-21 10:42:09,182 |jsse-nio-8443-exec-4 |FreeMarkerWorker              |I| loading properties:
> file:/C:/projectsASF/ofbiz/framework/webapp/config/freemarkerTransforms.properties
> 2018-10-21 10:42:09,183 |jsse-nio-8443-exec-4 |FreeMarkerWorker              |I| loading properties:
> file:/C:/projectsASF/ofbiz/framework/widget/config/freemarkerTransforms.properties
> 2018-10-21 10:42:09,184 |jsse-nio-8443-exec-4 |FreeMarkerWorker              |I| loading properties:
> file:/C:/projectsASF/ofbiz/applications/content/config/freemarkerTransforms.properties
> 2018-10-21 10:42:09,185 |jsse-nio-8443-exec-4 |FreeMarkerWorker              |I| loading properties:
> file:/C:/projectsASF/ofbiz/applications/product/config/freemarkerTransforms.properties
> 2018-10-21 10:42:09,368 |jsse-nio-8443-exec-4 |ScreenFactory                 |I| Got 27 screens in 0.202s from:
> file:/C:/projectsASF/ofbiz/themes/common-theme/widget/CommonScreens.xml
> 2018-10-21 10:42:09,376 |jsse-nio-8443-exec-4 |ScreenFactory                 |I| Got 8 screens in 0.007s from:
> file:/C:/projectsASF/ofbiz/plugins/example/widget/example/CommonScreens.xml
> 2018-10-21 10:42:09,724 |jsse-nio-8443-exec-4 |UtilProperties                |I| ResourceBundle CommonExtUiLabels (fr) created in 0.053s with 7
> properties
> 2018-10-21 10:42:09,725 |jsse-nio-8443-exec-4 |PrimaryKeyFinder              |I| Returning null because found incomplete primary key in find:
> [GenericEntity:PartyNameView][partyId,null()]
> 2018-10-21 10:42:09,845 |jsse-nio-8443-exec-4 |ServiceDispatcher             |T| Sync service [example/getLastSystemInfoNote] finished in [18]
> milliseconds
> 2018-10-21 10:42:10,342 |jsse-nio-8443-exec-4 |ServerHitBin                  |I| Visit delegatorName=default, ServerHitBin delegatorName=default
> 2018-10-21 10:42:10,352 |jsse-nio-8443-exec-4 |ControlServlet                |T| [[[main(Domain:https://localhost)] Request Done- total:4.053,since
> last([main(Domain:http...):4.053]]
>
> "Could not find userLogin for external login key: EL00e7af53-b4b5-40d8-bec2-56ea21563066" happened because I changed to another application after
> the session timed out, nothing abnormal.
>
>