Silence logback startup messages

[BardyBard]

Changes:

• Silenced logback startup messages, that are ran the first time you run setup_r5 are silenced.
• removed date from logfile to reduce clutter
• verbose = F = off, verbose = T = info
• version number is updated dynamically in java, by reading R properties
• console/file have separate levels, file always verbose = t

Example logback initialization messages:

17:50:05,551 |-INFO in ch.qos.logback.classic.LoggerContext[default] - This is logback-classic version v7.4
17:50:05,554 |-INFO in ch.qos.logback.classic.util.ContextInitializer@18a70f16 - No custom configurators were discovered as a service.
17:50:05,554 |-INFO in ch.qos.logback.classic.util.ContextInitializer@18a70f16 - Trying to configure with ch.qos.logback.classic.joran.SerializedModelConfigurator
17:50:05,555 |-INFO in ch.qos.logback.classic.util.ContextInitializer@18a70f16 - Constructed configurator of type class ch.qos.logback.classic.joran.SerializedModelConfigurator
17:50:05,579 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.scmo]
17:50:05,580 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.scmo]
... etc ...

[BardyBard]

@rafapereirabr A couple of things I'd like your opinion on.

1. I have personally found it very annoying that a new r5r log file is created every day, so after a week I get a buildup of these files. Since we have switched to overwriting the log file instead of keeping a record of every command, I think it makes sense to remove the date from the log file so that you only ever have one log file that gets overwritten even on the next day. Let me know if you want me to make this change.

2. Currently we only support verbose = true/false. The actual logback implementation supports these levels in hierarchical order: OFF, ERROR, WARN, INFO, DEBUG, TRACE, ALL. The little jar sets ERROR for verbose = false and ALL for verbose = true.

I think verbose = T, should set INFO, not ALL. As debug and trace are very specific messages that I don't think they have much use for a user looking at only the R side of the code, and they significantly clutter the screen. While INFO still gives a much greater output than only ERROR but makes it much more palatable to process the information. Some example messages of DEBUG are:

17:50:48.267 [ForkJoinPool.commonPool-worker-1] DEBUG com.conveyal.r5.streets.StreetRouter - Using time limit of 3600 sec
17:50:48.267 [ForkJoinPool.commonPool-worker-4] DEBUG com.conveyal.r5.streets.StreetRouter - Using time limit of 3600 sec
17:50:48.267 [ForkJoinPool.commonPool-worker-6] DEBUG com.conveyal.r5.streets.StreetRouter - Using time limit of 3600 sec
17:50:48.267 [ForkJoinPool.commonPool-worker-2] DEBUG com.conveyal.r5.streets.StreetRouter - Using time limit of 3600 sec

17:50:48.279 [ForkJoinPool.commonPool-worker-3] DEBUG com.conveyal.r5.streets.StreetRouter - Routing took 12 msec
17:50:48.279 [ForkJoinPool.commonPool-worker-2] DEBUG com.conveyal.r5.streets.StreetRouter - Routing took 12 msec

17:50:48.281 [ForkJoinPool.commonPool-worker-7] DEBUG com.conveyal.r5.profile.ExecutionTimer - - Pattern filtering: 2.94E-5s
17:50:48.281 [ForkJoinPool.commonPool-worker-7] DEBUG com.conveyal.r5.profile.ExecutionTimer - - Scheduled/bounds search: 0.0049156s
17:50:48.281 [ForkJoinPool.commonPool-worker-7] DEBUG com.conveyal.r5.profile.ExecutionTimer - - - Scheduled search: 0.0034816s
17:50:48.281 [ForkJoinPool.commonPool-worker-7] DEBUG com.conveyal.r5.profile.ExecutionTimer - - - Frequency upper bounds: 0.0s
17:50:48.281 [ForkJoinPool.commonPool-worker-7] DEBUG com.conveyal.r5.profile.ExecutionTimer - - - Transfers: 4.941E-4s
17:50:48.281 [ForkJoinPool.commonPool-worker-7] DEBUG com.conveyal.r5.profile.ExecutionTimer - - - other: 9.399E-4s
17:50:48.281 [ForkJoinPool.commonPool-worker-7] DEBUG com.conveyal.r5.profile.ExecutionTimer - - Frequency search: 0.0s
17:50:48.281 [ForkJoinPool.commonPool-worker-7] DEBUG com.conveyal.r5.profile.ExecutionTimer - - - Frequency component: 0.0s
17:50:48.281 [ForkJoinPool.commonPool-worker-7] DEBUG com.conveyal.r5.profile.ExecutionTimer - - - Resulting updates to scheduled component: 0.0s
17:50:48.281 [ForkJoinPool.commonPool-worker-7] DEBUG com.conveyal.r5.profile.ExecutionTimer - - - Transfers: 0.0s
17:50:48.281 [ForkJoinPool.commonPool-worker-7] DEBUG com.conveyal.r5.profile.ExecutionTimer - - other: 0.0014456s

17:50:48.308 [ForkJoinPool.commonPool-worker-5] DEBUG com.conveyal.r5.profile.ExecutionTimer - - Pattern filtering: 2.59E-5s
17:50:48.308 [ForkJoinPool.commonPool-worker-5] DEBUG com.conveyal.r5.profile.ExecutionTimer - - Scheduled/bounds search: 0.0095746s

[BardyBard]

@rafapereirabr
3. I think it could also be interesting to expose the OFF, ERROR, WARN, INFO, DEBUG, TRACE, ALL level setting to the user in R. This way the user can decide what level of detail they want instead of us hiding that functionality from them. It would allow for a more progressive debugging process for the user, instead of having just on/off. If they have a bug they can try looking at the WARN messages, then move on to INFO messages, and perhaps some power user might find DEBUG helpful. It makes finding important messages in a wall of text easier.

This would be extremely easy from the little jar implementation side. From the R side we refactor all verbose variables to be Strings instead of Booleans with a default of "ERROR" (same result as current implementation). And in the documentation we explain you can pass verbose = "WARN" and verbose = "INFO". This does introduce added complexity however, as now the user can't just guess that there is a verbose paramater and write = TRUE, they actually have to read which strings it accepts.

Perhaps we can "grandfather" verbose = T to be equal to verbose = "INFO". I'm not sure if its possible for variables in R to be strings and booleans at the same time?

[rafapereirabr]

1. I think it's Ok if the log file is overwritten with the last setup_r5() call.
2. The notion of ERROR seems to be different in R packages and in R5. In R, an ERROR necessarily stops the function, which is not necessarily the case in R5. Having said that, I need to think a bit more about this. We can discuss points 2 and 3 in our next meeting.

[rafapereirabr]

• when verbose = FALSE, we use OFF
• when verbose = TRUE, we use ERROR, WARN, INFO
  • No debug messages

[BardyBard]

• rename file
• verbose = F = off verbose = T = info
• change verion number dynamically in java
• console/file have separate levels, file always verbose = t

[BardyBard]

@rafapereirabr Branch is ready for merging.

While having separate logging levels for the console and the logfile would in theory be possible. It looks like it wouldn't be that simple to implement and add complexity to maintaining. I suggest we either open a separate issue for it, or forget about the idea.

[rafapereirabr]

Thanks, @BardyBard . I'm Ok with using the same logging levels in the console and log file. No problem!
Are we ready to merge this PR then ?

[BardyBard]

Yes we are!

[rafapereirabr]

fantastic ! will merge it now. ! we'll just need to update the NEWS file