Skip to Content.
Sympa Menu

grouper-dev - [grouper-dev] RE: loader log is very chatty and full of lines of questionable value....

Subject: Grouper Developers Forum

List archive

[grouper-dev] RE: loader log is very chatty and full of lines of questionable value....


Chronological Thread 
  • From: "Hyzer, Chris" <>
  • To: "Black, Carey M." <>
  • Cc: "" <>
  • Subject: [grouper-dev] RE: loader log is very chatty and full of lines of questionable value....
  • Date: Tue, 29 Aug 2017 16:22:36 +0000
  • Accept-language: en-US
  • Authentication-results: spf=none (sender IP is ) ;
  • Ironport-phdr: 9a23:ulckuhfXPpI3KQsZlTxjuPZylGMj4u6mDksu8pMizoh2WeGdxcW6Yx7h7PlgxGXEQZ/co6odzbGH4+a4ASQp2tWoiDg6aptCVhsI2409vjcLJ4q7M3D9N+PgdCcgHc5PBxdP9nC/NlVJSo6lPwWB6nK94iQPFRrhKAF7Ovr6GpLIj8Swyuu+54Dfbx9GiTe5Yr5+Ngm6oRnMvcQKnIVuLbo8xAHUqXVSYeRWwm1oJVOXnxni48q74YBu/SdNtf8/7sBMSar1cbg2QrxeFzQmLns65Nb3uhnZTAuA/WUTX2MLmRdVGQfF7RX6XpDssivms+d2xSeXMdHqQb0yRD+v9LlgRgP2hygbNj456GDXhdJ2jKJHuxKquhhzz5fJbI2JKPZye6XQds4YS2VcRMZcTyxPDJ2hYYsTAeQPPuhYoIv8p1QSohWxChKhBP/2yjNUmnP6wbE23/onHArb3AIgBdUOsHHModn7NqkTUeG0w7fSzTnbcvhbxzf96JLJchA6r/2HQLV9cc/NxkkvFwLEj0ufqZb+MjOUzeQCr3KX7/d4Ve2xjW4nrRt9rSayyccxk4TEgJ8exF7D9SV82ok1JNu4RVZ6Yd6iDJtfqTuaN41oTcM+XW1kojg1xaAbuZO9YSMEy4wnygbBZ/CbcYWE+B3uWeeLLTtlhX9odqiziwi8/ES41+HxWNW43ExOoyZYiNXAqG0B2hjJ5sSaSPZw/0Gs0iuV2Q/J8OFLO0U0mLLbK5E/xr4wkYIev1zfEyHxhEn7graaeEsj9OWm8ujnZa7pqYGGO49zlwH+Lr8hmsuiAeQ+LwcCRXCb+f671L3/40L2XKlKjvwxkqnfqpzaItkbprK9Aw9S1YYj6AyzACuh0NQdhXUHLVRFdwybj4XxJV3CPPL1Ae2wjlmtijtn2vHLM7P7DpnTIHXPiLLhcqx8605Yxgoz19df55dMB7EEPP3zWk/wtd3GAR8jKAG0wv3nB8ln2oMDQWKAHKmZMKXIvVCW++0vPvGAZJUJtzblN/gl+/nugGc2mV8HeqmpwIMXZ26iHvh/PkqWf2Tsj8wFEWcLpQo+UPfqhEOYXT5SYXayQ7wz5is9CI24EYfPWJqhj6Kc0yemTdVqYTUMIFSFGnSsP66NQfodIAfUaIc1mDgNXrvnEtV6/Ra1qUn3x6cxfcTO/ShN/7LyxtVvo6X4lQsz7nY8W8GW03CfQntcn3gDASIu0aZ550Fx1wHQguBDn/VEGIkLtLtyWQAgOMuZlrQiBg==
  • Spamdiagnosticmetadata: NSPM
  • Spamdiagnosticoutput: 1:99

Did you see this so you don't need to use this INFO logging anymore?

https://spaces.internet2.edu/display/Grouper/Grouper+daemon+log

But yes, I can address this, good catch

Thanks
Chris

-----Original Message-----
From: Black, Carey M.
[mailto:]

Sent: Monday, August 28, 2017 6:31 PM
To: Hyzer, Chris
<>
Cc:

Subject: RE: loader log is very chatty and full of lines of questionable
value....

Logging enhancement request:

grouper/grouper/src/grouper/edu/internet2/middleware/grouper/app/loader/GrouperLoaderType.java

There are more than a few places (in the same class, maybe elsewhere too... I
have not gone fishing yet...) where I think the same error was repeated.

Example: Line: 4302
"
if (LOG.isInfoEnabled() && (count[0] != 0 && count[0] % 200 == 0)) {
LOG.info(groupName + " adding: " + count + " of " + numberOfRows + "
subjects"
+ (alreadyAdded ? ", [note: was already added... weird]" : ""));
}
"

count is not the same as count[0] .

I think this is causing the issue that I described in another email thread as:
" Looks like an "integer" is not being referenced properly in a few places. (
" adding: [I@6596eb12 of 29774 subjects" ) "


And if you really want to "make it a bit better"....

Move that "magic string" (200) out to a config value so that I can log every
1000, or 5000, or 100,000 based on my environments needs.
And if you really want to go one step farther... move that config to the
loader job definition so that I can control that value per job instead of a
global, hard coded value.
( And why is it 200 in some places and 500 in others? Hum.... more than
one new config value needed? )

--
Carey Matthew



-----Original Message-----
From: Hyzer, Chris
[mailto:]

Sent: Saturday, August 19, 2017 6:20 PM
To: Black, Carey M.
<>;
Redman, Chad
<>;


Cc:

Subject: RE: loader log is very chatty and full of lines of questionable
value....

I made a patch that has better grouper daemon specific logging. This is a
starting point. Let me know what you think and if other things need to be
logged or if things need not to be logged :) Note, the threads that are
involved in the loader make this complex, so I marked it as a high risk
patch, though if you don't enable it, it shouldn't affect anything. I am
currently running this so I can see how it does. Anyways, experimental at
this point.

fixed in 2.3.0 api patch #77

https://spaces.internet2.edu/display/Grouper/Grouper+daemon+log

Note, if you are in an existing install, and you apply the patch, you need to
add the two sections to the log4j.properties to enable this.

https://bugs.internet2.edu/jira/browse/GRP-1590

Thanks
Chris



-----Original Message-----
From:


[mailto:]
On Behalf Of Black, Carey M.
Sent: Friday, August 18, 2017 4:32 PM
To: Redman, Chad
<>;


Cc:

Subject: [grouper-dev] RE: loader log is very chatty and full of lines of
questionable value....

Chad,

Thanks for the insights.

I will enable the two " grouper.app.loader.GrouperLoader [Config | Type ] "
settings and see if those are more helpful.

My heartburn is that I think the other lines ( non ' session: start' ) are
useful. But I appear to have to take 4 "bad lines" to get 1 "good one". (
Not a great trade off. And not clear as to why that is the current, default,
condition.) So I hate to lose the good to get rid of the bad. ( But it looks
like I need to do that just to keep from filling up disks. :) )

Maybe the classes you pointed at will give me similar insights to what the
loader is or is not doing.
Thanks again. ( I am still finding my way through the configuration and
tuning. I have a feeling that this will take a bit of time to polish....)

--
Carey Matthew



-----Original Message-----
From: Redman, Chad
[mailto:]

Sent: Friday, August 18, 2017 2:55 PM
To: Black, Carey M.
<>;


Cc:

Subject: RE: loader log is very chatty and full of lines of questionable
value....

The default log4.properties has:

## Grouper Event Logging
## * Logs at _info_ only
log4j.logger.edu.internet2.middleware.grouper.log.EventLog = INFO,
grouper_event

We took that out for our loader. The log4j settings we currently have on our
loader server are:

--------------------------
log4j.appender.R = org.apache.log4j.FileAppender
log4j.appender.R.File = ${log4j.filename.sync}
log4j.appender.R.layout = org.apache.log4j.PatternLayout
log4j.appender.R.layout.ConversionPattern = %d{ISO8601}: [%t] %-5p
%C{1}.%M(%L) - %m%n

log4j.rootLogger = WARN, R

## All Internet2 (warn to grouper_error per default logger)
log4j.logger.edu.internet2.middleware = WARN

log4j.logger.edu.internet2.middleware.grouper.RegistryInstall = INFO

log4j.logger.edu.internet2.middleware.grouper.app.loader.GrouperLoaderType =
DEBUG

log4j.logger.edu.internet2.middleware.grouper.app.loader.GrouperLoaderConfig
= DEBUG
--------------------------

The GrouperLoaderType DEBUG setting is pretty useful for summarizing some of
the actual loader actions. The GrouperLoaderConfig DEBUG doesn't print out
very much, just the LDAP settings periodically.

Maybe the EventLog logging of session starts can be changed to print at level
debug instead of info? For a while, we had kept the level at info only in the
UI, because there was no other way to see who was logging in. But we
eventually turned it off in the UI as well, being too verbose.

-Chad




-----Original Message-----
From:


[mailto:]
On Behalf Of Black, Carey M.
Sent: Friday, August 18, 2017 2:14 PM
To:

Cc:

Subject: [grouper-dev] RE: loader log is very chatty and full of lines of
questionable value....

Bump.

I am seeing 1G log files created per day.
4721929 lines that have ' session: start'
1153101 lines that do not.

That is 4.7M lines of logs that end up in our splunk system that provide no
known useful information.

Does anyone else see this on their systems?
Does anyone use the Grouper Loader process?

Any hints about how to make the logging better? ( Other than track down the
line of code and wrapper it with an if block. )

--
Carey Matthew



-----Original Message-----
From:


[mailto:]
On Behalf Of Black, Carey M.
Sent: Wednesday, August 16, 2017 2:57 PM
To:

Subject: [grouper-users] loader log is very chatty and full of lines of
questionable value....

I am trying to use the Loader process to sync some data into grouper from
LDAP. ( That part is working as far as I can tell after I gave it enough ram
to not fall over. :) )


However, in the grouper_error.log (for where the loader is logging) I am
seeing a lot of lines like :
"
2017-08-16 14:25:04,783: [DefaultQuartzScheduler_Worker-7] INFO
EventLog.info(156) - - [9a3e8...c35b,'GrouperSystem','application'] session:
start (0ms) "

And by a lot I mean ( Just from today's file...):

$ wc -l grouper_error.log ; grep -c ' session: start' grouper_error.log; grep
-vc ' session: start' grouper_error.log;
3135034 grouper_error.log ( Total lines in the file)
2379686 ( Lines that are ' session: start' lines, 75% of the file!)
755517 ( Lines that are not ' session: start' lines )

Can anyone tell me how to suppress ONLY those lines?
I might be wrong but other lines that say things like "add member" ,
"delete member" (etc...) look like they are being logged from the same
location. [ AKA: " INFO EventLog.info(156)" ]

Could any explain why those log statements are there?
I really don't understand what they are trying to communicate.

--
Carey Matthew






Archive powered by MHonArc 2.6.19.

Top of Page