Add command-line parameter to silence non-error log messages

[dhersz]

Is your feature request related to a problem? Please describe.

I'm creating a function on the {gtfstools} R package that wraps the command-line tool and validates a GTFS (validate_gtfs()). The function also saves the command output (stderr and stdout as separate files) together with the usual validation output.

I haven't yet seen case where something was outputted to stdout, but stderr is always full of log messages. These log messages, however, are usually not so relevant to an user that doesn't know the internals of the validator. For example, this is what the stderr of the validation mentioned in #1193 looks like:

Click to see stderr

jun 22, 2022 1:39:40 PM org.mobilitydata.gtfsvalidator.runner.ValidationRunner run
INFO: VersionInfo: VersionInfo{currentVersion=Optional[3.1.0], latestReleaseVersion=Optional[3.1.0]}
jun 22, 2022 1:39:41 PM org.mobilitydata.gtfsvalidator.runner.ValidationRunner run
INFO: validation config:
ValidationRunnerConfig{gtfsSource=file:///home/dhersz/Documents/repos/gtfstools/inst/extdata/poa_gtfs.zip, outputDirectory=/tmp/RtmpYoqwg7/new_validation_result32284e8cded4, storageDirectory=Optional.empty, validationReportFileName=report.json, htmlReportFileName=report.html, systemErrorsReportFileName=system_errors.json, numThreads=1, countryCode=ZZ, prettyJson=false}
jun 22, 2022 1:39:41 PM org.mobilitydata.gtfsvalidator.runner.ValidationRunner run
INFO: validators:
Single-entity validators
	GtfsCalendar: GtfsCalendarEndRangeValidator 
	GtfsFrequency: GtfsFrequencyEndRangeValidator 
	GtfsAttribution: AttributionWithoutRoleValidator 
	GtfsPathway: PathwayLoopValidator 
	GtfsShape: GtfsShapeLatLonValidator 
	GtfsStopTime: GtfsStopTimeEndRangeValidator 
	GtfsFeedInfo: FeedExpirationDateValidator FeedServiceDateValidator GtfsFeedInfoEndRangeValidator 
	GtfsStop: GtfsStopLatLonValidator LocationTypeSingleEntityValidator StopNameValidator 
	GtfsRoute: RouteColorContrastValidator RouteNameValidator 
Single-file validators
	GtfsShapeTableContainer: ShapeIncreasingDistanceValidator 
	GtfsFareRuleTableContainer: DuplicateFareRuleZoneIdFieldsValidator 
	GtfsRouteTableContainer: DuplicateRouteNameValidator 
	GtfsAgencyTableContainer: AgencyConsistencyValidator 
	GtfsStopTimeTableContainer: MissingTripEdgeValidator StopTimeArrivalAndDepartureTimeValidator StopTimeIncreasingDistanceValidator TimepointTimeValidator 
	GtfsFrequencyTableContainer: OverlappingFrequencyValidator 
	GtfsStopTableContainer: ParentLocationTypeValidator 
Multi-file validators
	BlockTripsWithOverlappingStopTimesValidator GtfsAttributionAgencyIdForeignKeyValidator GtfsAttributionRouteIdForeignKeyValidator GtfsAttributionTripIdForeignKeyValidator GtfsFareAttributeAgencyIdForeignKeyValidator GtfsFareRuleContainsIdForeignKeyValidator GtfsFareRuleDestinationIdForeignKeyValidator GtfsFareRuleFareIdForeignKeyValidator GtfsFareRuleOriginIdForeignKeyValidator GtfsFareRuleRouteIdForeignKeyValidator GtfsFrequencyTripIdForeignKeyValidator GtfsPathwayFromStopIdForeignKeyValidator GtfsPathwayToStopIdForeignKeyValidator GtfsRouteAgencyIdForeignKeyValidator GtfsStopLevelIdForeignKeyValidator GtfsStopParentStationForeignKeyValidator GtfsStopTimeStopIdForeignKeyValidator GtfsStopTimeTripIdForeignKeyValidator GtfsTransferFromStopIdForeignKeyValidator GtfsTransferToStopIdForeignKeyValidator GtfsTripRouteIdForeignKeyValidator GtfsTripServiceIdForeignKeyValidator GtfsTripShapeIdForeignKeyValidator LocationHasStopTimesValidator MatchingFeedAndAgencyLangValidator MissingCalendarAndCalendarDateValidator MissingLevelIdValidator PathwayDanglingGenericNodeValidator PathwayEndpointTypeValidator PathwayReachableLocationValidator ShapeToStopMatchingValidator ShapeUsageValidator StopTimeTravelSpeedValidator StopZoneIdValidator TranslationFieldAndReferenceValidator TripAgencyIdValidator TripUsabilityValidator TripUsageValidator UrlConsistencyValidator 

jun 22, 2022 1:39:41 PM org.mobilitydata.gtfsvalidator.table.GtfsFeedLoader loadAndValidate
INFO: Loading in 1 threads
jun 22, 2022 1:39:41 PM org.mobilitydata.gtfsvalidator.table.GtfsAgencyTableLoader load
INFO: Cache for agency.txt agency_lang: size = 1, lookup count = 1, hits = 0.00%, misses = 100.00%
jun 22, 2022 1:39:41 PM org.mobilitydata.gtfsvalidator.table.GtfsCalendarTableLoader load
INFO: Cache for calendar.txt start_date: size = 2, lookup count = 2236, hits = 99.91%, misses = 0.09%
jun 22, 2022 1:39:41 PM org.mobilitydata.gtfsvalidator.table.GtfsCalendarTableLoader load
INFO: Cache for calendar.txt end_date: size = 2, lookup count = 2236, hits = 99.91%, misses = 0.09%
jun 22, 2022 1:39:41 PM org.mobilitydata.gtfsvalidator.table.GtfsRouteTableLoader load
INFO: Cache for routes.txt agency_id: size = 1, lookup count = 4, hits = 75.00%, misses = 25.00%
jun 22, 2022 1:39:41 PM org.mobilitydata.gtfsvalidator.table.GtfsRouteTableLoader load
INFO: Cache for routes.txt route_color: size = 2, lookup count = 8, hits = 75.00%, misses = 25.00%
jun 22, 2022 1:39:41 PM org.mobilitydata.gtfsvalidator.table.GtfsRouteTableLoader load
INFO: Cache for routes.txt route_text_color: size = 2, lookup count = 8, hits = 75.00%, misses = 25.00%
jun 22, 2022 1:39:41 PM org.mobilitydata.gtfsvalidator.table.GtfsRouteTableLoader load
SEVERE: Failed to parse some rows in routes.txt
jun 22, 2022 1:39:41 PM org.mobilitydata.gtfsvalidator.table.GtfsShapeTableLoader load
INFO: Cache for shapes.txt shape_id: size = 4, lookup count = 1265, hits = 99.68%, misses = 0.32%
jun 22, 2022 1:39:41 PM org.mobilitydata.gtfsvalidator.table.GtfsStopTimeTableLoader load
INFO: Cache for stop_times.txt trip_id: size = 387, lookup count = 23040, hits = 98.32%, misses = 1.68%
jun 22, 2022 1:39:41 PM org.mobilitydata.gtfsvalidator.table.GtfsStopTimeTableLoader load
INFO: Cache for stop_times.txt arrival_time: size = 521, lookup count = 46080, hits = 98.87%, misses = 1.13%
jun 22, 2022 1:39:41 PM org.mobilitydata.gtfsvalidator.table.GtfsStopTimeTableLoader load
INFO: Cache for stop_times.txt departure_time: size = 521, lookup count = 46080, hits = 98.87%, misses = 1.13%
jun 22, 2022 1:39:41 PM org.mobilitydata.gtfsvalidator.table.GtfsStopTimeTableLoader load
INFO: Cache for stop_times.txt stop_id: size = 212, lookup count = 23040, hits = 99.08%, misses = 0.92%
jun 22, 2022 1:39:41 PM org.mobilitydata.gtfsvalidator.table.GtfsStopTimeTableLoader load
INFO: Cache for stop_times.txt stop_headsign: size = 0, lookup count = 23040, hits = 100.00%, misses = 0.00%
jun 22, 2022 1:39:41 PM org.mobilitydata.gtfsvalidator.table.GtfsStopTableLoader load
INFO: Cache for stops.txt zone_id: size = 0, lookup count = 212, hits = 100.00%, misses = 0.00%
jun 22, 2022 1:39:41 PM org.mobilitydata.gtfsvalidator.table.GtfsStopTableLoader load
INFO: Cache for stops.txt parent_station: size = 0, lookup count = 212, hits = 100.00%, misses = 0.00%
jun 22, 2022 1:39:41 PM org.mobilitydata.gtfsvalidator.table.GtfsStopTableLoader load
INFO: Cache for stops.txt level_id: size = 0, lookup count = 212, hits = 100.00%, misses = 0.00%
jun 22, 2022 1:39:41 PM org.mobilitydata.gtfsvalidator.table.GtfsTripTableLoader load
INFO: Cache for trips.txt route_id: size = 4, lookup count = 387, hits = 98.97%, misses = 1.03%
jun 22, 2022 1:39:41 PM org.mobilitydata.gtfsvalidator.table.GtfsTripTableLoader load
INFO: Cache for trips.txt service_id: size = 13, lookup count = 387, hits = 96.64%, misses = 3.36%
jun 22, 2022 1:39:41 PM org.mobilitydata.gtfsvalidator.table.GtfsTripTableLoader load
INFO: Cache for trips.txt block_id: size = 0, lookup count = 387, hits = 100.00%, misses = 0.00%
jun 22, 2022 1:39:41 PM org.mobilitydata.gtfsvalidator.table.GtfsTripTableLoader load
INFO: Cache for trips.txt shape_id: size = 4, lookup count = 387, hits = 98.97%, misses = 1.03%
SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
jun 22, 2022 1:39:42 PM org.mobilitydata.gtfsvalidator.runner.ValidationRunner printSummary
SEVERE:  ----------------------------------------- 
|       !!!    PARSING FAILED    !!!      |
|   Most validators were never invoked.   |
|   Please see report.json for details.   |
 ----------------------------------------- 

jun 22, 2022 1:39:42 PM org.mobilitydata.gtfsvalidator.runner.ValidationRunner printSummary
INFO: Validation took 1.219 seconds

jun 22, 2022 1:39:42 PM org.mobilitydata.gtfsvalidator.runner.ValidationRunner printSummary
INFO: agency.txt	1
attributions.txt	MISSING_FILE
calendar.txt	1118
calendar_dates.txt	MISSING_FILE
fare_attributes.txt	MISSING_FILE
fare_rules.txt	MISSING_FILE
feed_info.txt	MISSING_FILE
frequencies.txt	MISSING_FILE
levels.txt	MISSING_FILE
pathways.txt	MISSING_FILE
routes.txt	UNPARSABLE_ROWS
shapes.txt	1265
stop_times.txt	23040
stops.txt	212
transfers.txt	MISSING_FILE
translations.txt	MISSING_FILE
trips.txt	387

The SEVERE message aside, none of the other log messages are relevant to an user that doesn't know the tool internals (except the last one, maybe, that summarizes the feed - but even the number of rows in each file is not that relevant of an information). The INFO messages log stuff like the internal validators used, cache hits on each table, the number of threads used, etc.

Thus, important error messages are hidden (or at least harder to see) because they are mixed with informative and not as important to end user messages.

Proposed solution

I suggest adding a command-line parameter (e.g. --quiet or -q) that suppress INFO messages when used. Error messages (such as SEVERE) would always be outputted to stderr, even if this parameter was used.

Describe alternatives you've considered

I'm not sure if the suggested behaviour can be accomplished in any other way. I could redirect stderr to /dev/null, for example, but then I'd lose the error messages as well. I could potentially create a "log cleaner" as well, that manually removes the INFO messages and keeps only the error messages, but I'd be much more comfortable doing that from R, thus not benefiting the wider audience that uses this tool from the command-line or from other programming languages.

[barbeau]

I agree, this is annoying.

This same issue came up with the gtfs-rt-validator - MobilityData/gtfs-realtime-validator#98.

From what I recall it's a quirk of the current Java logging framework being used. Even if you log something as "error" or "debug", there is effectively one pipe coming out of the logging framework, and by default this gets output to stderr. You can configure the framework to redirect everything to stdout instead, but there isn't an option to split for example "debug" to stdout and "error" to stderr.

So IIRC the only way to fix this is to switch logging frameworks.

[dhersz]

To be fair, I think that all these logs should be piped to stderr, and not to to stdout, because the output of the validator are the html and json files, not the log messages.

My suggestion would only control which messages are outputted, not where.

I was thinking, for example, that this line

gtfs-validator/main/src/main/java/org/mobilitydata/gtfsvalidator/runner/ValidationRunner.java

Line 150 in cec914e

logger.atInfo().log("Validation took %.3f seconds%n", (endNanos - startNanos) / 1e9);

that outputs how long validation took, could be wrapped in a if (!quiet) { .... } block, thus preventing it from printed when --quiet is specified (I'm not sure how CLI args parsing works in Java, I'm just assuming the quiet param could be parsed as bool and then saved in a quiet variable).

[barbeau]

@dhersz Thanks for the feedback! Sounds like your approach to switching parts of the log on/off is similar in concept to #256?

I should also note that it's been a while since I've looked at the logging implementation in this project, so it's worth doing a review there to see if the same limitations apply here that we saw in MobilityData/gtfs-realtime-validator#98.

[dhersz]

That's exactly it. Sorry for opening this issue then, I had searched for "quiet" but somehow forgot search for "verbose".

Should we just close this issue and keep the discussion on the other one you linked to?

[barbeau]

No worries - I'd leave this open, and focus it on the stdout vs stderr output, as I think that's bound to come up again (as it already has for the gtfs-rt-validator). Both issues are very valid topics for improvements to the validator, IMHO.

Could you comment on #256 with your expectations for how it would be implemented, just to document that in context? And 👍 that issue too?