Fix unstructured logging variable formatting

[aysim319]

Description

replacing logging with f strings with parameters

Associated Issue(s)

• Addresses Fix unstructured logging variable formatting #2025

[melange396]

looks pretty good! i marked a few things i think you mightve missed, and tried to change filename= where it actually referred to a directory and not a singular file.

[dshemetov]

Match the above?

Suggested change

	logger.info("No data for signal", signal=f"{geo_res}_{metric.lower()}_{sensor_name}")
	logger.info("No data for signal", geo_res=geo_res, metric=metric.lower(), sensor_name=sensor_name)

[aysim319]

I wasn't sure since the original log wanted to capture it as a signal and not into seperate metric, sensor, geo....

[dshemetov]

Yea, these old pipelines like to mix together geo resolution, metric and sensor name into a single name and call it signal, though that doesn't match our definition of signal anywhere else. Seems better to me to separate these out, since then you can do granular search in the logs without doing substring search.

[melange396]

Two lines below this is a call to create_export_csv() which combines metric and sensor in the output file name, in what will ultimately be the signal name. How about:

Suggested change

	logger.info("No data for signal", signal=f"{geo_res}_{metric.lower()}_{sensor_name}")
	logger.info("No data for signal", geo_type=geo_res, signal=f"{metric}_{sensor_name}")

Should we use this opportunity to add better logging to create_export_csv()? @aysim319, you have something planned to change doctor visits and hospital admissions to use this method, right? Perhaps we can add the logging then.

[aysim319]

yeah.. I think it's better to revisit once all the indicators are using create_export_csv... because at least for hospital-admissions it doesn't quite use the metric and the sensor combination if I recall

[aysim319]

looks pretty good! i marked a few things i think you mightve missed, and tried to change filename= where it actually referred to a directory and not a singular file.

Ah yeah, that was an intentional choice. I didn't see any output_path being used and it techincally also has the filename so whynot and worst comes to worst someone tells me it's not right and i'd fix it.

[melange396]

im gonna set this to "draft" and then back again to try to get ci to re-run

[dshemetov]

We'll likely make more adjustments, but this seems like a nice incremental change for the better to me. Let's make an issue to follow up on a few more changes once all indicators are migrated to create_export_csv.

[aysim319]

./changehc/delphi_changehc/sensor.py:121: logger.debug("{0}: {1:.3f},[{2:.3f}]".format(
./changehc/delphi_changehc/update_sensor.py:52: logger.warning("value suspiciously high, {0}: {1}".format(
./changehc/delphi_changehc/update_sensor.py:149: self.logger.error("{0} is invalid, pick one of 'county', "
./doctor_visits/delphi_doctor_visits/sensor.py:242: logger.debug(f"{geo_id}: {new_rates[-1]:.3f},[{se[-1]:.3f}]")
./claims_hosp/delphi_claims_hosp/indicator.py:146: logging.debug("%s: %05.3f, [%05.3f]

The second one is one that I missed and third one, I didn't feel like parameterizing a wrong value made sense, but I could also see why it would be helpful...

But for the rest, I think it's better to leave it as is as they're debugging logs where I think seeing the message as is seems more helpful instead of having it parameterized.

Edited changed all of the instance

[aysim319]

@dshemetov since you and david is planning a formatting PR, thought I ping you about this
getting inconsistent behavior for darker:
similar isssue: psf/black#1140

in _delphi_utils.delphi_utils.runner.py
line 63-66 and 82:
local darker wants one line

# Logging - Starting Indicator
        logger.info("Started a covidcast-indicator", indicator_name=ind_name, current_version=current_version)
    else:
        logger.info("Started a covidcast-indicator without version.cfg", indicator_name=ind_name)      

logger.error("Flash step timed out, terminating", elapsed_time_in_seconds=round(time.time() - start, 2))

CI wants multi-line

@@ -62,11 +62,11 @@
                     current_version = current_version.replace("current_version = ", "")
     #Logging - Starting Indicator
         logger.info(
             "Started a covidcast-indicator",
             indicator_name=ind_name,
-            current_version=current_version
+            current_version=current_version,
         )
     else:
         logger.info(
             "Started a covidcast-indicator without version.cfg", indicator_name=ind_name
         )
@@ -83,13 +83,14 @@
             logger.info("Completed flash step",
                     elapsed_time_in_seconds = round(time.time() - start, 2))
             break
         time.sleep(1)
     else:
-        logger.error("Flash step timed out, terminating",
-                     elapsed_time_in_seconds=round(time.time() - start, 2)
-                 )
+        logger.error(
+            "Flash step timed out, terminating",
+            elapsed_time_in_seconds=round(time.time() - start, 2),
+        )

[dshemetov]

Hm, is it resolved now or did you have to manually adjust it to make CI happy? I might need to point the format commands in both CI and Makefiles to the pyproject.toml just to eliminate the possibility that they're not finding it (it specifies line-length = 120 there and this seems like a disagreement about line-length).

[aysim319]

Hm, is it resolved now or did you have to manually adjust it to make CI happy? I might need to point the format commands in both CI and Makefiles to the pyproject.toml just to eliminate the possibility that they're not finding it (it specifies line-length = 120 there and this seems like a disagreement about line-length).

I had to manually adjust it .... :/

[melange396]

last ones!

[melange396]

@aysim319 i removed some stray files that somehow wandered into your last commit, and i changed the format of a reverted logger call back to make it pass linting.