onfly_checksum Warnings

[douglatornell]

I've been seeing a large number of onfly_checksum warning messages in the log file since we switched to collecting the HRDPS continental grid forecast files from hpfx.collab.science.gc.ca in late February 2023. We are using sarracenia version 2.22.10post2. Below are:

• A log fragment showing the warnings. Not every file has an associated warning, but the vast majority do.
• A log fragment showing an sr_subscribe startup yesterday
• The sr_subscribe config file

We have been using sarracenia for several years. Prior to 22-Feb-2023 we were collecting much smaller files from the HRDPS west domain forecasts. I never recall seeing any onfly_checksum warnings from those files. The continental files we are collecting now don't appear to be corrupted, so I am curious what the warning is about.

I'd appreciate any advice on this.

Thanks...

Doug Latornell
Research Software Engineer
Earth, Ocean & Atmospheric Sciences Department, UBC

Log fragment:

2023-04-17 11:34:27,010 [INFO] heartbeat. Sarracenia version is: 2.22.10post2 

2023-04-17 11:34:27,011 [INFO] hb_memory cpu_times user=113.63 system=27.44 elapse=41877403.05
2023-04-17 11:34:27,011 [INFO] hb_memory, current usage: 59.7 MiB trigger restart if increases past: 175.9 MiB 
2023-04-17 11:34:27,011 [INFO] hb_retry on_heartbeat
2023-04-17 11:34:27,011 [INFO] sr_retry on_heartbeat
2023-04-17 11:34:27,020 [INFO] No retry in list
2023-04-17 11:34:27,023 [INFO] sr_retry on_heartbeat elapse 0.011259
2023-04-17 11:34:55,410 [WARNING] onfly_checksum n,4042f41a4c6c6a4d4b1866d1550703b8 differ from message n,850e003843e69ac60afb85739061808a
2023-04-17 11:34:55,475 [INFO] file_log downloaded to: /SalishSeaCast/datamart/hrdps-continental/12/047/20230417T12Z_MSC_HRDPS_TMP_AGL-2m_RLatLon0.0225_PT047H.grib2
2023-04-17 11:35:01,883 [INFO] file_log downloaded to: /SalishSeaCast/datamart/hrdps-continental/12/046/20230417T12Z_MSC_HRDPS_PRMSL_MSL_RLatLon0.0225_PT046H.grib2
2023-04-17 11:35:06,526 [WARNING] onfly_checksum n,7e30669cf2671b6b1cb7cef0b05ec2be differ from message n,ee3fdff6e3b60d37be3c3b8e5e7c3429
2023-04-17 11:35:06,586 [INFO] file_log downloaded to: /SalishSeaCast/datamart/hrdps-continental/12/046/20230417T12Z_MSC_HRDPS_LHTFL_Sfc_RLatLon0.0225_PT046H.grib2
2023-04-17 11:35:07,907 [INFO] file_log downloaded to: /SalishSeaCast/datamart/hrdps-continental/12/046/20230417T12Z_MSC_HRDPS_PRATE_Sfc_RLatLon0.0225_PT046H.grib2
2023-04-17 11:35:28,181 [WARNING] onfly_checksum n,03eeac4355ffa5ad568e37c73c0d8048 differ from message n,46a279a108092ea3eff3fdae897dd893
2023-04-17 11:35:28,241 [INFO] file_log downloaded to: /SalishSeaCast/datamart/hrdps-continental/12/046/20230417T12Z_MSC_HRDPS_RH_AGL-2m_RLatLon0.0225_PT046H.grib2
2023-04-17 11:35:33,636 [WARNING] onfly_checksum n,0df0e3584f973d603a42c62831397329 differ from message n,deaab5436a9117250e57a98efe49e65a
2023-04-17 11:35:33,694 [INFO] file_log downloaded to: /SalishSeaCast/datamart/hrdps-continental/12/047/20230417T12Z_MSC_HRDPS_UGRD_AGL-10m_RLatLon0.0225_PT047H.grib2
2023-04-17 11:35:45,573 [WARNING] onfly_checksum n,efe1dd79300a64e9efc84e6781179da5 differ from message n,83fb48128e35c88916508cc99bcb4148
2023-04-17 11:35:45,629 [INFO] file_log downloaded to: /SalishSeaCast/datamart/hrdps-continental/12/046/20230417T12Z_MSC_HRDPS_SPFH_AGL-2m_RLatLon0.0225_PT046H.grib2
2023-04-17 11:36:02,414 [WARNING] onfly_checksum n,7141ed23388e251cb4acd4a99e9a327d differ from message n,f0bd2c265a13bbaded76fa04e9c61c74
2023-04-17 11:36:02,471 [INFO] file_log downloaded to: /SalishSeaCast/datamart/hrdps-continental/12/047/20230417T12Z_MSC_HRDPS_VGRD_AGL-10m_RLatLon0.0225_PT047H.grib2

sr_suscribe startup log:

2023-04-16 17:26:39,299 [INFO] sr_subscribe hrdps-continental-hpfx start
2023-04-16 17:26:39,299 [INFO] log settings start for sr_subscribe (version: 2.22.10post2):
2023-04-16 17:26:39,300 [INFO]  inflight=.tmp events=create|delete|link|modify use_pika=False topic_prefix=v02.post dry_run=False
2023-04-16 17:26:39,300 [INFO]  inline=False events=create|delete|link|modify use_amqplib=False topic_prefix=v02.post
2023-04-16 17:26:39,300 [INFO]  suppress_duplicates=False basis=path retry_mode=True retry_ttl=10800000ms tls_rigour=normal
2023-04-16 17:26:39,300 [INFO]  expire=10800000ms reset=False message_ttl=None prefetch=25 accept_unmatch=False delete=False poll_without_vip=True
2023-04-16 17:26:39,300 [INFO]  heartbeat=300 sanity_log_dead=450 default_mode=000 default_mode_dir=775 default_mode_log=600 discard=False durable=True
2023-04-16 17:26:39,300 [INFO]  declare_queue=True declare_exchange=True bind_queue=True
2023-04-16 17:26:39,301 [INFO]  post_on_start=True preserve_mode=True preserve_time=True realpath_post=False base_dir=None follow_symlinks=False
2023-04-16 17:26:39,301 [INFO]  mirror=True flatten=/ realpath_post=False strip=6 base_dir=None report_back=True log_reject=False
2023-04-16 17:26:39,301 [INFO]  Plugins configured:
2023-04-16 17:26:39,301 [INFO]          do_download: 
2023-04-16 17:26:39,301 [INFO]          do_get     : 
2023-04-16 17:26:39,301 [INFO]          on_message: 
2023-04-16 17:26:39,301 [INFO]          on_data: 
2023-04-16 17:26:39,301 [INFO]          on_part: 
2023-04-16 17:26:39,302 [INFO]          on_file: File_Log 
2023-04-16 17:26:39,302 [INFO]          on_post: Post_Log 
2023-04-16 17:26:39,302 [INFO]          on_heartbeat: Hb_Log Hb_Memory RETRY 
2023-04-16 17:26:39,302 [INFO]          on_report: 
2023-04-16 17:26:39,302 [INFO]          on_start: 
2023-04-16 17:26:39,302 [INFO]          on_stop: 
2023-04-16 17:26:39,302 [INFO] log_settings end.
2023-04-16 17:26:39,302 [INFO] sr_subscribe run
2023-04-16 17:26:39,303 [INFO] AMQP  broker(hpfx.collab.science.gc.ca) user(anonymous) vhost(/)
2023-04-16 17:26:39,303 [INFO] Using amqp module (AMQP 0-9-1)
2023-04-16 17:26:40,179 [INFO] Binding queue q_anonymous.sr_subscribe.hrdps-continental-hpfx.UBC.SalishSeaCast with key v02.post.*.WXO-DD.model_hrdps.continental.2.5km.# from exchange xpublic on broker amqps://anonymous@hpfx.collab.science.gc.ca/
2023-04-16 17:26:40,292 [INFO] declared queue q_anonymous.sr_subscribe.hrdps-continental-hpfx.UBC.SalishSeaCast (anonymous@hpfx.collab.science.gc.ca) 
2023-04-16 17:26:40,350 [INFO] reading from to anonymous@hpfx.collab.science.gc.ca, exchange: xpublic
2023-04-16 17:26:40,463 [INFO] report_back to anonymous@hpfx.collab.science.gc.ca, exchange: xs_anonymous
2023-04-16 17:26:40,463 [INFO] sr_retry on_heartbeat
2023-04-16 17:26:40,472 [INFO] No retry in list
2023-04-16 17:26:40,475 [INFO] sr_retry on_heartbeat elapse 0.010858

sr_subscribe config file:

queue_name q_anonymous.sr_subscribe.hrdps-continental-hpfx.UBC.SalishSeaCast
instances 1
expire 3h

subtopic *.WXO-DD.model_hrdps.continental.2.5km.#
directory /SalishSeaCast/datamart/hrdps-continental/
# mirror the datamart directory structure but drop the 1st 4 path elements
# so that our mirror starts with forecast number (00/, 06/, 12/, or 18/)
mirror true
strip 6

# we only want 001/ directories onward
reject .*?/000/.*
# don't want WEonG (Weather Elements on Grid) version of variables
reject .*WEonG_PRATE_Sfc.*
reject .*WEonG_FZPRATE_Sfc.*

# u component of wind velocity at 10m elevation
accept .*UGRD_AGL-10m.*
# v component of wind velocity at 10m elevation
accept .*VGRD_AGL-10m.*
# accumulated downward shortwave (solar) radiation at ground level
accept .*DSWRF_Sfc.*
# accumulated downward longwave (thermal) radiation at ground level
accept .*DLWRF_Sfc.*
# upward surface latent heat flux (for VHFR FVCOM)
accept .*LHTFL_Sfc.*
# air temperature at 2m elevation
accept .*TMP_AGL-2m.*
# specific humidity at 2m elevation
accept .*SPFH_AGL-2m.*
# relative humidity at 2m elevation (for VHFR FVCOM)
accept .*RH_AGL-2m.*
# accumulated precipitation at ground level
accept .*APCP_Sfc.*
# precipitation rate at ground level (for VHFR FVCOM)
accept .*PRATE_Sfc.*
# atmospheric pressure at mean sea level
accept .*PRMSL_MSL.*

[reidsunderland]

Hi @douglatornell, sorry it took a while for someone to get back to you. The n indicates that the checksum is an md5sum on the filename, which explains why you haven't had issues with the files being corrupted when you see the warnings.

The cause of the problem seems to be that the checksum in the message is being calculated from the filename with a ".tmp" suffix. This comes from our internal systems, which append ".tmp" to the filename while it's still being downloaded and then remove it when the download is complete.

2023-04-17 11:36:02,414 [WARNING] onfly_checksum n,7141ed23388e251cb4acd4a99e9a327d differ from message n,f0bd2c265a13bbaded76fa04e9c61c74
2023-04-17 11:36:02,471 [INFO] file_log downloaded to: /SalishSeaCast/datamart/hrdps-continental/12/047/20230417T12Z_MSC_HRDPS_VGRD_AGL-10m_RLatLon0.0225_PT047H.grib2

>>> filename1="20230417T12Z_MSC_HRDPS_VGRD_AGL-10m_RLatLon0.0225_PT047H.grib2"
>>> filename2="20230417T12Z_MSC_HRDPS_VGRD_AGL-10m_RLatLon0.0225_PT047H.grib2.tmp"
>>> md5(bytes(filename1,'utf-8')).hexdigest()
'7141ed23388e251cb4acd4a99e9a327d'
>>> md5(bytes(filename2,'utf-8')).hexdigest()
'f0bd2c265a13bbaded76fa04e9c61c74'

We'll work on a fix for this problem, but it's safe to ignore the warnings in the meantime. Thanks for letting us know about this!

[reidsunderland]

I created issue #679 for this.

[douglatornell]

Thanks for the explanation @reidsunderland .