Logging standardization: standardize logger declarations, parameterize log calls, fix stack traces, replace println, add outcome logging - #137
Conversation
nutjob4life
left a comment
nutjob4life
left a comment
There was a problem hiding this comment.
I'm getting a compilation error when I try this patch:
mirasol 283 % cd /tmp
/tmp
mirasol 284 % git clone --branch super_log --quiet git@github.com:NASA-PDS/registry-loader.git
mirasol 285 % cd registry-loader/
/tmp/registry-loader
mirasol 286 % mvn --quiet clean test
null --> null
--> null
2013-10-24T00:00:00Z --> 2013-10-24T00:00:00Z
2013-10-24T00:49:37.457Z --> 2013-10-24T00:49:37.457Z
2013-302T01:02:03.123 --> 2013-10-29T01:02:03.123Z
2013-302T01:02:03.123Z --> 2013-10-29T01:02:03.123Z
2016-09-08Z --> 2016-09-08T00:00:00Z
2013-03-02 --> 2013-03-02T00:00:00Z
2013-12 --> 2013-12-01T00:00:00Z
2013 --> 2013-01-01T00:00:00Z
2015Z --> 2015-01-01T00:00:00Z
2013-001 --> 2013-01-01T00:00:00Z
[ERROR] COMPILATION ERROR :
[ERROR] /private/tmp/registry-loader/manager/src/main/java/gov/nasa/pds/registry/mgr/dao/RegistryDao.java:[61,42] cannot find symbol
symbol: method altIds()
location: interface gov.nasa.pds.registry.common.Response.Search
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-compiler-plugin:3.8.1:compile (default-compile) on project registry-manager: Compilation failure
[ERROR] /private/tmp/registry-loader/manager/src/main/java/gov/nasa/pds/registry/mgr/dao/RegistryDao.java:[61,42] cannot find symbol
[ERROR] symbol: method altIds()
[ERROR] location: interface gov.nasa.pds.registry.common.Response.Search
[ERROR]
[ERROR] -> [Help 1]
[ERROR]
[ERROR] To see the full stack trace of the errors, re-run Maven with the -e switch.
[ERROR] Re-run Maven using the -X switch to enable full debug logging.
[ERROR]
[ERROR] For more information about the errors and possible solutions, please read the following articles:
[ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/MojoFailureException
[ERROR]
[ERROR] After correcting the problems, you can resume the build with the command
[ERROR] mvn <args> -rf :registry-manager
48.925u 7.000s 0:29.19 191.5% 0+0k 0+0io 16pf+0wMaybe I have an out-of-date dependency?
|
Well, the build works! |
jordanpadams
left a comment
jordanpadams
left a comment
There was a problem hiding this comment.
Integration tests fail which is expected at this time
|
Thanks for the work here — the direction is right. A few gaps and one bug to address before merging: #127 — Bug:
|
|
@al-niessner wrote:
Woo-hoo! |
|
Hey Mr Ai, Yes to #129. See note on ticket. It states these are used by test to see private parts of class. Good as is. If tests are unused/unwanted that is something different. |
|
Still builds! |
…rized calls - Fix #130: Convert all logger fields to private static final Logger log = LogManager.getLogger(ClassName.class) across common, harvest, and manager. Eliminates per-instance logger objects, local-variable loggers, and LOG/logger naming inconsistencies. - Fix #131: Replace string-concatenation log calls ("msg: " + var) with parameterized form ("msg: {}", var) across all three modules. Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>
jordanpadams
changed the title
|
@al-niessner @nutjob4life rolled in additional updates for #130 and #131 |
| log.log(LogUtils.LEVEL_SUMMARY, "Loaded files: " + processedCount); | ||
| log.log(LogUtils.LEVEL_SUMMARY, "Label Failure: {} (database rejected label/product)", counter.failedFileCount); | ||
| log.log(LogUtils.LEVEL_SUMMARY, "Label Ignored: {} (files that are not readable as label/product)", counter.ignoredFileCount); | ||
| log.log(LogUtils.LEVEL_SUMMARY, "Label Matched: {} (batch rejected as duplicate lidvid)", counter.matchedFileCount); |
There was a problem hiding this comment.
I think this will always say:
Label Matched: 0 (batch rejected as duplicate lidvid)
Because DataLoader.loadBatch() now takes Set<String> matchedIds and MetadataWriter expects it to drive:
counter.matchedFileCount += matchedIds.size();But when the code encounters an HTTP code 409 (which, by the way, could be replaced with HttpURLConnection.HTTP_CONFLICT) , it only does:
log.log(LogLevels.LABEL_MATCHED, sanitizedLidvid);
todo.remove(asKey(item));There is no counterpart code that does something like
if (matchedIds != null) matchedIds.add(item.id());so the new summary ends up always being zero.
If that logic makes sense, then I'd consider this a blocker.
There was a problem hiding this comment.
You want matched to always be 0. There is a race condition from latency with AOSS or there is the case of two harvests over same data at same time problem. harvest checks and thinks lidvid needs to be inserted and uploads it. Mean while already in place batch or other process has already injected it so this harvest gets an error from opensearch that lidvid matches. hence the count.
Scoff if you like. The check would not be there if we had not tripped over at least once. So either/both of these conditions exist in the real world.
| || (nonRegisteredIds != null && nonRegisteredIds.contains(item.lidvid) | ||
| && !failedIds.contains(item.lidvid))) { | ||
| counter.prodCounters.inc(item.prodClass); | ||
| log.log(LogLevels.LABEL_SUCCESS, item.lidvid); |
There was a problem hiding this comment.
While this handles the !failedIds.contains(item.lidvid) case, where is the !matchedIds.contains(item.lidvid) case? Even after fixing the "blocker" described above for Label Matched: 0, a duplicate rejected with HTTP CONFLICT ("409"), can still fall through this code and get
LABEL MATCHED urn:...
LABEL SUCCESS urn:...
and increment the product-success counter.
Depending on the intended semantics of nonRegisteredIds, this should be
if (nonRegisteredIds == null
|| (nonRegisteredIds.contains(item.lidvid)
&& !failedIds.contains(item.lidvid)
&& !matchedIds.contains(item.lidvid))) {More generally, there are 5 states, right?
- FAILURE
- IGNORED
- MATCHED
- SKIPPED
- SUCCESS
And they're all mutually exclusive. The implementation should enforce that as an invariant rather than deriving each counter independently.
There was a problem hiding this comment.
There are 5 states but your bot needs to look around to see them all. Since we want clear counting, ignored, matched, and skipped are all similar quasi pass or fail. See summary comments to their difference. All 5 states are accounted for but lumping them would contravene the clarity requirement/request.
| public static final Level LABEL_FAILURE = Level.forName("LABEL FAILURE", 121); // batch did not accept lidvid | ||
| public static final Level LABEL_IGNORED = Level.forName("LABEL IGNORED", 122); // file could not be read as a label | ||
| public static final Level LABEL_MATCHED = Level.forName("LABEL MATCHED", 123); // batch rejected as duplicate lidvid | ||
| public static final Level LABEL_SKIPPED = Level.forName("LABEL SKIPPED", 124); // the lidvid was already in database | ||
| public static final Level LABEL_SUCCESS = Level.forName("LABEL SUCCESS", 125); // batch accepted lidvid |
There was a problem hiding this comment.
These levels are 121…125, but the Log4j standard levels are roughly
FATAL 100
ERROR 200
WARN 300
INFO 400
DEBUG 500
TRACE 600
So all the LABEL_* levels aren't fatal, but are more severe than ERROR.
If someone runs with
-v ERROR
they'll still get
LABEL SUCCESS
LABEL SKIPPED
…
LABEL FAILURE
and likewith with WARN. If this is deliberate, great, and ignore this comment.
There was a problem hiding this comment.
Just expanded what was there, but think the idea is that 100 makes them non-filtered. They will still show with -v ERROR because it works on being less than 200. I guess you could turn them off -v FATAL. Anyway, just extended what was there. If the user does -v FATAL then they deserve not see the summary.
|
@al-niessner I hate to be a pain here, but can you attach what an example output log would actually look like so I can verify these meet the requirement expectations? Or provide examples of each? It may just be easier to update the end user documentation at https://github.com/NASA-PDS/registry regarding logging |
|
Happy to update, but what files actually need editing? Not sure how things are built and did not see anything specific in root readme as I scrolled through it in 5 seconds nor a file that said set-user-expectation.edit.me or logging.edit.me or anything else. |
|
@al-niessner nothing needs updating, I just don't know what an output log would look like from a user perspective when harvest is run. I need that to determine if this is what we want. |
|
Did a small run so here is the full log file: Are Product_Document counted? Looks like not. Maybe there are 2 versions of something so success is 1 less than total? |
|
@al-niessner all labels (products) should be counted. the product type is irrelevant. |
|
Well, you can make this ticket last indefinitely but having me chase down the count discrepancy again, or call it done and create a new ticket for counting. Fixing the counting is a repetitive chore. I would prefer to do it with the test harness rather than ad-hoc in this ticket though. |
|
@jordanpadams I count 3 bundles, 3 collections, 1 document, and 13 kernels in the harvest (easy, short log). Seems collections is off by 1. |
3 participants
Summary
Comprehensive logging standardization across the
common,harvest, andmanagermodules, addressing a backlog of logging issues and adding operator-facing outcome logging:Log4jConfiguratorfrom harvest + manager intocommonwith a sharedLogLevelsclass (includesSUMMARY,LABEL_SUCCESS,LABEL_FAILURE,LABEL_SKIPPEDlevels)System.out.printlncalls in production code with properlog.warn/log.debugcallsprivate static final Logger log = LogManager.getLogger(ClassName.class); eliminates per-instance loggers and local-variable loggers"msg: {}",var) across all three modulesslf4j-nopversion in parent pom so both modules use the same versiones/) client classes,UpdateAltIdsCmd, and related test infrastructureAI Assistance Disclosure
Estimated % of code influenced by AI: 40 %
Test Data and/or Report
Related Issues
Fixes #126
Fixes #127
Fixes #128
Fixes #129
Fixes #130
Fixes #131
Fixes #132
Reviewer Checklist
Documentation and PR Content
Security & Quality
Testing & Validation
Maintenance