Task #9708

Something slipped into the latest smartgears distributions that set the logging level to DEBUG

Added by Andrea Dell'Amico over 2 years ago. Updated about 2 years ago.

Status:ClosedStart date:Sep 18, 2017
Priority:ImmediateDue date:
Assignee:Andrea Dell'Amico% Done:

100%

Category:distribution
Sprint:zz - Smartgears
Milestones:
Duration:

Description

@luca.frosini@isti.cnr.it saw something on its installations, and the new geonetwork2-tunaatlas.d4science.org is also logging at DEBUG level while logback.xml is set to WARN or FATAL.


Related issues

Related to D4Science Infrastructure - Task #9942: Change the way to generate the logback.xml in smartgears ... Closed Oct 12, 2017
Related to gCube - Feature #10715: Create fake-accounting-lib Closed Dec 15, 2017
Related to D4Science Infrastructure - Support #10972: DataMiner - Disk space problems Closed Jan 18, 2018

History

#1 Updated by Luca Frosini over 2 years ago

I didn't experienced such a behaviour disabling logging accounting in a separated file (i.e. accountin.log)

#2 Updated by Roberto Cirillo over 2 years ago

It seems this problem wasn't happened during the preproduction upgrade (4th September). So, I guess, there is something changed or added after the preproduction upgrade which had cause this problem. I'm going to investigate.

#3 Updated by Roberto Cirillo over 2 years ago

it should be also noted that on geonetwork2-tunaatlas.d4science.org there are only two rows with DEBUG set:

07:50:31.323 [AccountingScheduledThread-27] DEBUG AggregationScheduler: PersistenceCouchBase will be used.
07:51:28.196 [AccountingScheduledThread-31] DEBUG AggregationScheduler: PersistenceCouchBase will be used.

it seems only "accounting scheduler" log level is set to debug not the whole distribution.

#4 Updated by Andrea Dell'Amico over 2 years ago

There are more:

accounting.2017-09-18.log:19:47:28.043 [catalina-exec-1] DEBUG PersistenceBackendFactory: Creating FallbackPersistenceBackend for context /d4science.research-infrastructures.eu
accounting.2017-09-18.log:19:47:29.067 [AccountingScheduledThread-0] DEBUG PersistenceBackendFactory: The PersistenceBackend for context /d4science.research-infrastructures.eu is FallbackPersistenceBackend. Is time to rediscover if there is another possibility.
accounting.2017-09-18.log:19:47:29.067 [AccountingScheduledThread-0] DEBUG PersistenceBackendFactory: Discovering PersistenceBackend for scope /d4science.research-infrastructures.eu
accounting.2017-09-18.log:19:47:31.126 [AccountingScheduledThread-0] DEBUG PersistenceCouchBase: PersistenceCouchBase prepareConnection url:http://couchbase01.d4science.org, http://couchbase02.d4science.org, http://couchbase03.d4science.org, http://couchbase04.d4science.org, http://couchbase05.d4science.org, http://couchbase06.d4science.org, http://couchbase07.d4science.org, http://couchbase08.d4science.org and now is connectionsMap:{}
accounting.2017-09-18.log:19:51:28.190 [AccountingScheduledThread-1] DEBUG FallbackPersistenceBackend: reallyAccount:{"recordType":"ServiceUsageRecord","resourceProperties":{"operationCount":1,"creationTime":1505756848085,"serviceClass":"SDI","callerHost":"146.48.122.27","callerQualifier":"UNKNOWN","recordType":"ServiceUsageRecord","consumerId":"UNKNOWN","aggregated":true,"serviceName":"GeoNetwork","duration":2847,"maxInvocationTime":2847,"scope":"/d4science.research-infrastructures.eu","host":"geonetwork2-tunaatlas.d4science.org:80","startTime":1505756848043,"id":"98585173-f457-43b4-8dc4-6cdd2e99ea3f","calledMethod":"/srv/eng/catalog.search;jsessionid=76BF882719B821A037DEA61ECEC12FF4","endTime":1505756848043,"minInvocationTime":2847,"operationResult":"SUCCESS"}}
accounting.2017-09-18.log:19:58:29.766 [AccountingScheduledThread-4] DEBUG RecordUtility: Unmarshal record with jackson
accounting.log:07:50:31.323 [AccountingScheduledThread-27] DEBUG AggregationScheduler: PersistenceCouchBase will be used.
accounting.log:07:51:28.196 [AccountingScheduledThread-31] DEBUG AggregationScheduler: PersistenceCouchBase will be used.
ghn.2017-09-18.log:19:47:28.043 [catalina-exec-1] DEBUG PersistenceBackendFactory: Creating FallbackPersistenceBackend for context /d4science.research-infrastructures.eu
ghn.2017-09-18.log:19:47:29.067 [AccountingScheduledThread-0] DEBUG PersistenceBackendFactory: The PersistenceBackend for context /d4science.research-infrastructures.eu is FallbackPersistenceBackend. Is time to rediscover if there is another possibility.
ghn.2017-09-18.log:19:47:29.067 [AccountingScheduledThread-0] DEBUG PersistenceBackendFactory: Discovering PersistenceBackend for scope /d4science.research-infrastructures.eu
ghn.2017-09-18.log:19:47:31.126 [AccountingScheduledThread-0] DEBUG PersistenceCouchBase: PersistenceCouchBase prepareConnection url:http://couchbase01.d4science.org, http://couchbase02.d4science.org, http://couchbase03.d4science.org, http://couchbase04.d4science.org, http://couchbase05.d4science.org, http://couchbase06.d4science.org, http://couchbase07.d4science.org, http://couchbase08.d4science.org and now is connectionsMap:{}
ghn.2017-09-18.log:19:51:28.190 [AccountingScheduledThread-1] DEBUG FallbackPersistenceBackend: reallyAccount:{"recordType":"ServiceUsageRecord","resourceProperties":{"operationCount":1,"creationTime":1505756848085,"serviceClass":"SDI","callerHost":"146.48.122.27","callerQualifier":"UNKNOWN","recordType":"ServiceUsageRecord","consumerId":"UNKNOWN","aggregated":true,"serviceName":"GeoNetwork","duration":2847,"maxInvocationTime":2847,"scope":"/d4science.research-infrastructures.eu","host":"geonetwork2-tunaatlas.d4science.org:80","startTime":1505756848043,"id":"98585173-f457-43b4-8dc4-6cdd2e99ea3f","calledMethod":"/srv/eng/catalog.search;jsessionid=76BF882719B821A037DEA61ECEC12FF4","endTime":1505756848043,"minInvocationTime":2847,"operationResult":"SUCCESS"}}
ghn.2017-09-18.log:19:58:29.766 [AccountingScheduledThread-4] DEBUG RecordUtility: Unmarshal record with jackson
ghn.log:07:50:31.323 [AccountingScheduledThread-27] DEBUG AggregationScheduler: PersistenceCouchBase will be used.
ghn.log:07:51:28.196 [AccountingScheduledThread-31] DEBUG AggregationScheduler: PersistenceCouchBase will be used.

But yes, they all seem accounting related and this fits with the @luca.frosini@isti.cnr.it experience.

#5 Updated by Luca Frosini over 2 years ago

  • Sprint changed from gCube Release 4.6.1 to zz - Smartgears

#6 Updated by Pasquale Pagano about 2 years ago

  • Tracker changed from Bug to Task

What is this? Is a bug opened as urgent one month ago ? .. first I am going to change the tracker since it does not seem to be a bug, then close it or solve it, please.

#7 Updated by Andrea Dell'Amico about 2 years ago

  • Related to Task #9942: Change the way to generate the logback.xml in smartgears container added

#8 Updated by Andrea Dell'Amico about 2 years ago

Yes, it should be solved. There also another task that asks for a revision of the logback configuration, #9942. I just added it as a related one.

#9 Updated by Massimiliano Assante about 2 years ago

is this going to be solved in 4.9.0? Can we apply a temporary patch ASAP?

#10 Updated by Luca Frosini about 2 years ago

I experienced that if we remove the configuration that logs in 3 different files the level is maintained to the configured level.

#11 Updated by Luca Frosini about 2 years ago

  • Priority changed from Urgent to Immediate

@lucio.lelii@isti.cnr.it please take care of it

#12 Updated by Andrea Dell'Amico about 2 years ago

Note that this not solves the real problem nor the actual one: the workspace logs are filling up the disk space at a rhythm of some GB in a few minutes at ERROR level. The errors are those ones: http://paste.d4science.org/index.php?id=20171214140803_20969 (this is a matter of a different ticket I guess)

#13 Updated by Andrea Dell'Amico about 2 years ago

I just opened #10667

#14 Updated by Pasquale Pagano about 2 years ago

I don't understand this ticket. From the log attached, it seems related to the Accounting, thus to @luca.frosini@isti.cnr.it. The issue has to be solved now since it compromises a node till killing it.

#15 Updated by Luca Frosini about 2 years ago

#16 Updated by Andrea Dell'Amico about 2 years ago

I've found the problem. The FATAL log level that was assigned to the accounting loggers does not exist (I don't even want to know where it comes from), and logback maps all the invalid log level to DEBUG (globally, it seems).

I just changed the accounting log level to ERROR in the playbook template for logback. I also changed the default configuration settings to

<configuration scan="true" debug="false">

The scan option makes the file automatically reloaded when the configuration changes, so it's not necessary to restart tomcat anymore when the configuration changes. The debug option permits to check the logback configuration when tomcat starts. The output goes to the standard output (logback is not yet active when the configuration is being checked). I used the debug option to find the wrong settings.

#17 Updated by Andrea Dell'Amico about 2 years ago

  • % Done changed from 0 to 100
  • Assignee changed from Lucio Lelii to Andrea Dell'Amico
  • Status changed from New to Closed

#18 Updated by Andrea Dell'Amico about 2 years ago

Also available in: Atom PDF