move many logging events to debug

[andkay]

@fredshone I have drastically reduce the amount of logging output by moving most events being tracked to the DEBUG level.

INFO level logging now just tells users about when the program starts, event/plan iteration progress, minimised info about handlers writing files, and benchmark scores as applicable.

There are a couple additional fixes we could tack onto this, but I'm stuck on:

1. Running elara with DEBUG logging hooks logging from matplotlib which is super un-helpful.
2. For iteration progress, it would be very desirable to keeping logging on a single console line.

I've also fixed some instances where the class (rather than the name of the class) was being included in the message: INFO building <class 'elara.benchmarking.TestPTInteraction'>: bus: .... In doing that, I've replaced most instances of self.__str__() with str(self) to be consistent and shorter.

[andkay]

The INFO level log for example config now looks like this

10-19 15:58 elara.main   INFO Starting
10-19 15:58 elara.config INFO  *** Created RequirementsWorkStation
10-19 15:58 elara.postprocessing INFO  *** Created PostProcessWorkStation
10-19 15:58 elara.inputs INFO  *** Created InputsWorkStation
10-19 15:58 elara.config INFO  *** Created PathFinderWorkStation
10-19 15:58 elara.event_handlers INFO  *** Created EventHandlerWorkStation
10-19 15:58 elara.plan_handlers INFO  *** Created PlanHandlerWorkStation
10-19 15:58 elara.benchmarking INFO  *** Created BenchmarkWorkStation
10-19 15:58 elara.factory INFO All Workstations Initiated and Validated
10-19 15:58 elara.factory INFO Initiating Build
10-19 15:58 elara.plan_handlers INFO  *** Commencing Plans Iteration ***
10-19 15:58 elara.plan_handlers INFO parsed 1 persons plans
10-19 15:58 elara.plan_handlers INFO parsed 2 persons plans
10-19 15:58 elara.plan_handlers INFO parsed 4 persons plans
10-19 15:58 elara.plan_handlers INFO ***Completed Plan Iteration***
10-19 15:58 elara.plan_handlers INFO Writing results from ModeSharesAll to ./outputs
10-19 15:58 elara.factory INFO Chunkwriter finished for ./outputs/leg_logs_all_activities.csv
10-19 15:58 elara.factory INFO Chunkwriter finished for ./outputs/leg_logs_all_legs.csv
10-19 15:58 elara.factory INFO Chunkwriter finished for ./outputs/trip_logs_all_activities.csv
10-19 15:58 elara.factory INFO Chunkwriter finished for ./outputs/trip_logs_all_trips.csv
10-19 15:58 elara.plan_handlers INFO Writing results from AgentHighwayDistanceLogsCar to ./outputs
10-19 15:58 elara.factory INFO Chunkwriter finished for ./outputs/trip_highway_distance_logs_car.csv
10-19 15:58 elara.event_handlers INFO ***Commencing Event Iteration***
10-19 15:58 elara.event_handlers INFO parsed 1 events
10-19 15:58 elara.event_handlers INFO parsed 2 events
10-19 15:58 elara.event_handlers INFO parsed 4 events
10-19 15:58 elara.event_handlers INFO parsed 8 events
10-19 15:58 elara.event_handlers INFO parsed 16 events
10-19 15:58 elara.event_handlers INFO parsed 32 events
10-19 15:58 elara.event_handlers INFO parsed 64 events
10-19 15:58 elara.event_handlers INFO parsed 128 events
10-19 15:58 elara.event_handlers INFO *** Completed Event Iteration ***
10-19 15:58 elara.event_handlers INFO Writing results from LinkVehicleCountsBus to ./outputs
10-19 15:58 elara.event_handlers INFO Writing results from LinkVehicleCountsCar to ./outputs
10-19 15:58 elara.event_handlers INFO Writing results from LinkPassengerCountsBus to ./outputs
10-19 15:58 elara.event_handlers INFO Writing results from StopPassengerCountsBus to ./outputs
10-19 15:58 elara.factory INFO Chunkwriter finished for ./outputs/StopPassengerWaitingAll.csv
10-19 15:58 elara.event_handlers INFO Writing results from StopToStopPassengerCountsBus to ./outputs
10-19 15:58 elara.event_handlers INFO Writing results from VehicleStopToStopPassengerCountsBus to ./outputs
10-19 15:58 elara.factory INFO Chunkwriter finished for ./outputs/vehicle_departure_log_bus.csv
10-19 15:58 elara.factory INFO Chunkwriter finished for ./outputs/vehicle_passenger_log_bus.csv
10-19 15:58 elara.benchmarking INFO --BENCHMARK SCORES--
10-19 15:58 elara.benchmarking INFO  *** duration_comparison:all:None:./tests/test_outputs/trip_duration_breakdown_all.csv mse = 0.0 *** 
10-19 15:58 elara.benchmarking INFO  *** duration_comparison:all:None:./tests/test_outputs/trip_duration_breakdown_all.csv mae = 0.0 *** 
10-19 15:58 elara.benchmarking INFO  *** test_euclidean_distance_comparison:all:None: mse = 9.25 *** 
10-19 15:58 elara.benchmarking INFO  *** test_euclidean_distance_comparison:all:None: mae = 1.75 *** 
10-19 15:58 elara.benchmarking INFO  *** test_duration_comparison:all:None: mse = 0.0 *** 
10-19 15:58 elara.benchmarking INFO  *** test_duration_comparison:all:None: mae = 0.0 *** 
10-19 15:58 elara.benchmarking INFO  *** test_link_cordon:car:None: counters = 0.0 *** 
10-19 15:58 elara.benchmarking INFO  *** test_pt_interaction_counter:bus:None: counters = 0.0 *** 
10-19 15:58 elara.benchmarking INFO  *** Meta Score = 11.0 ***
10-19 15:58 elara.main   INFO Done

[fredshone]

great - i ran locally but couldn't get those logging from other packages - however in the past i had a similar issue with fiona so i do believe you. First thought is that this might be version dependant. Second thought was that it might be casued by the module level loggers - so i have removed these just in case.

[andkay]

I'm still getting irrelevant debug messages.

My best guess is that its because the specified config level is set on the module, and not a specific logger or handler, so the root logger gets set to debug. https://github.com/arup-group/elara/blob/dc94c92ebc4b62466a17cee1b435dc04bd0af65a/elara/main.py#L622

I'm going to open a separate issue for this.