better logging and more testing for large file indexes (#480)

* better logging * more progress * more progress * fixed new index format * fixed new index format
NOAA-EMC · Feb 5, 2024 · bae5225 · bae5225
1 parent 5a8e520
commit bae5225
Show file tree

Hide file tree

Showing 8 changed files with 97 additions and 59 deletions.
diff --git a/src/g2cfile.c b/src/g2cfile.c
@@ -315,7 +315,7 @@ g2c_get_msg(int g2cid, size_t skip_bytes, size_t max_bytes, size_t *bytes_to_msg
         *bytes_to_msg = bytes_to_msg_g;
         *bytes_in_msg = bytes_in_msg_g;
     }
-    LOG((3, "*bytes_to_msg %ld *bytes_in_msg %ld", *bytes_to_msg, *bytes_in_msg));
+    LOG((4, "*bytes_to_msg %ld *bytes_in_msg %ld", *bytes_to_msg, *bytes_in_msg));
 
     /* If no message was found, return an error. */
     if (*bytes_in_msg == 0)
@@ -800,7 +800,7 @@ add_section(FILE *f, G2C_MESSAGE_INFO_T *msg, int sec_id, unsigned int sec_len,
     G2C_SECTION_INFO_T *sec;
     int ret;
 
-    LOG((3, "add_section sec_id %d sec_len %d, bytes_to_sec %ld, sec_num %d",
+    LOG((4, "add_section sec_id %d sec_len %d, bytes_to_sec %ld, sec_num %d",
          sec_id, sec_len, bytes_to_sec, sec_num));
 
     /* Allocate storage for a new section. */
@@ -879,7 +879,7 @@ g2c_rw_section1_metadata(FILE *f, int rw_flag, G2C_MESSAGE_INFO_T *msg)
     unsigned char sec_num = 1;
     int ret;
 
-    LOG((2, "g2c_rw_section1_metadata rw_flag %d", rw_flag));
+    LOG((3, "g2c_rw_section1_metadata rw_flag %d", rw_flag));
 
     /* Read the section. */
     if ((ret = g2c_file_io_uint(f, rw_flag, (unsigned int *)&msg->sec1_len)))
@@ -1023,7 +1023,7 @@ add_msg(G2C_FILE_INFO_T *file, int msg_num, size_t bytes_to_msg, size_t bytes_in
     G2C_MESSAGE_INFO_T *my_msg;
     int ret;
 
-    LOG((3, "add_msg msg_num %d bytes_to_msg %ld bytes_in_msg %ld read_file %d",
+    LOG((4, "add_msg msg_num %d bytes_to_msg %ld bytes_in_msg %ld read_file %d",
          msg_num, bytes_to_msg, bytes_in_msg, read_file));
 
     /* Allocate storage for a new message. */
@@ -1090,15 +1090,15 @@ read_metadata(int g2cid)
     if (g2c_file[g2cid].g2cid != g2cid)
         return G2C_EBADID;
 
-    LOG((2, "read_metadata g2cid %d", g2cid));
+    LOG((4, "read_metadata g2cid %d", g2cid));
 
     /* Read each message in the file. */
     for (msg_num = 0; !ret; msg_num++)
     {
         /* Find the message. */
         if ((ret = g2c_seekmsg(g2cid, file_pos, &bytes_to_msg, &bytes_in_msg)))
             return ret;
-        LOG((3, "msg_num %d bytes_to_msg %ld bytes_in_msg %ld", msg_num, bytes_to_msg,
+        LOG((5, "msg_num %d bytes_to_msg %ld bytes_in_msg %ld", msg_num, bytes_to_msg,
              bytes_in_msg));
 
         /*  When there are 0 bytes_in_msg, we are done. */
@@ -1153,7 +1153,7 @@ g2c_add_file(const char *path, int mode, int *g2cid)
     if (!g2cid)
         return G2C_EINVAL;
 
-    LOG((1, "g2c_add_file path %s mode %d", path, mode));
+    LOG((3, "g2c_add_file path %s mode %d", path, mode));
 
     /* Find a file ID. */
     if ((ret = find_available_g2cid(g2cid)))
@@ -1235,7 +1235,7 @@ g2c_create(const char *path, int cmode, int *g2cid)
     if (!g2cid)
         return G2C_EINVAL;
 
-    LOG((1, "g2c_create path %s cmode %d", path, cmode));
+    LOG((2, "g2c_create path %s cmode %d", path, cmode));
 
     /* If NOCLOBBER, check if file exists. */
     if (cmode & G2C_NOCLOBBER)
@@ -1368,7 +1368,7 @@ g2c_close(int g2cid)
     if (g2c_file[g2cid].g2cid != g2cid)
         ret = G2C_EBADID;
 
-    LOG((1, "g2c_close %d", g2cid));
+    LOG((2, "g2c_close %d", g2cid));
 
     /* Free resources. */
     if (!ret)

diff --git a/src/g2cindex.c b/src/g2cindex.c
@@ -25,6 +25,9 @@ extern G2C_FILE_INFO_T g2c_file[G2C_MAX_FILES + 1];
 /** Length of beginning of index record. */
 #define G2C_INDEX_FIXED_LEN 44
 
+/** Length of beginning of index record for large files. */
+#define G2C_INDEX_FIXED_LEN_2 48
+
 /** Length of date string in index record. */
 #define G2C_INDEX_DATE_STR_LEN 10
 
@@ -77,6 +80,8 @@ g2c_start_index_record(FILE *f, int rw_flag, int *reclen, int *msg, int *local,
         || !msglen || !version || !discipline || !fieldnum)
         return G2C_EINVAL;
 
+    LOG((4, "g2c_start_index_record rw_flag %d", rw_flag));
+
     /* When writing, set the fieldnum1 to be a 1-based index, just
      * like in Fortran. */
     if (rw_flag)
@@ -152,6 +157,8 @@ g2c_start_index_record_lf(FILE *f, int rw_flag, int *reclen, size_t *msg, int *l
     short fieldnum1; /* This is for the 1-based fieldnum in the index file. */
     int ret;
 
+    LOG((4, "g2c_start_index_record_lf rw_flag %d", rw_flag));
+
     /* All pointers must be provided. */
     if (!f || !reclen || !msg || !local || !gds || !pds || !drs || !bms || !data
         || !msglen || !version || !discipline || !fieldnum)
@@ -444,7 +451,7 @@ g2c_write_index(int g2cid, int mode, const char *index_file)
     if (!index_file)
         return G2C_EINVAL;
 
-    LOG((1, "g2c_write_index g2cid %d mode %d index_file %s", g2cid, mode,
+    LOG((2, "g2c_write_index g2cid %d mode %d index_file %s", g2cid, mode,
          index_file));
 
     /* If NOCLOBBER, check if file exists. */
@@ -501,8 +508,8 @@ g2c_write_index(int g2cid, int mode, const char *index_file)
                     break;
 
                 /* What will be the length of this index record? */
-                reclen = G2C_INDEX_FIXED_LEN + msg->sec1_len + sec3->sec_len + sec4->sec_len +
-                    sec5->sec_len + G2C_INDEX_BITMAP_BYTES;
+                reclen = (index_version == 1 ? G2C_INDEX_FIXED_LEN : G2C_INDEX_FIXED_LEN_2) +
+		    msg->sec1_len + sec3->sec_len + sec4->sec_len + sec5->sec_len + G2C_INDEX_BITMAP_BYTES;
                 total_index_size += reclen;
                 LOG((4, "fieldnum %d reclen %d total_index_size %d", fieldnum, reclen, total_index_size));
             } /* next product */
@@ -550,8 +557,8 @@ g2c_write_index(int g2cid, int mode, const char *index_file)
                 bs7 = (int)sec7->bytes_to_sec;
 
                 /* What will be the length of this index record? */
-                reclen = G2C_INDEX_FIXED_LEN + msg->sec1_len + sec3->sec_len + sec4->sec_len +
-                    sec5->sec_len + G2C_INDEX_BITMAP_BYTES;
+                reclen = (index_version == 1 ? G2C_INDEX_FIXED_LEN : G2C_INDEX_FIXED_LEN_2)
+		    + msg->sec1_len + sec3->sec_len + sec4->sec_len + sec5->sec_len + G2C_INDEX_BITMAP_BYTES;
                 LOG((4, "fieldnum %d reclen %d", fieldnum, reclen));
 
                 /* Write the beginning of the index record. */
@@ -694,7 +701,7 @@ read_hdr_rec1(FILE *f, int *ip, int *jp, int *kp, char *date_str, char *time_str
 	memcpy(time_str, long_time_str, G2C_INDEX_TIME_STR_LEN);
 	time_str[G2C_INDEX_TIME_STR_LEN] = 0;
     }
-    LOG((2, "str1 %s i %d j %d k %d date_str %s time_str %s", str1, i, j, k, date_str,
+    LOG((4, "str1 %s i %d j %d k %d date_str %s time_str %s", str1, i, j, k, date_str,
 	 time_str));
 
     /* Return info to caller where desired. */
@@ -804,7 +811,7 @@ g2c_open_index1(const char *index_file)
     if (!index_file)
         return G2C_EINVAL;
 
-    LOG((1, "g2c_open_index1 index_file %s", index_file));
+    LOG((2, "g2c_open_index1 index_file %s", index_file));
 
     /* If using threading, lock the mutex. */
     MUTEX_LOCK(m);
@@ -816,12 +823,12 @@ g2c_open_index1(const char *index_file)
     /* Read header record apparently named after Steve Lord. */
     if ((ret = read_hdr_rec1(f, &i, &j, &k, date_str, time_str)))
 	return ret;
-    LOG((2, "i %d j %d k %d date_str %s time_str %s", i, j, k, date_str, time_str));
+    LOG((4, "i %d j %d k %d date_str %s time_str %s", i, j, k, date_str, time_str));
 
     /* Read second header record. */
     if ((ret = read_hdr_rec2(f, &skip, &total_len, &num_rec, basename, &index_version)))
 	return ret;
-    LOG((2, "skip %d total_len %d num_rec %d basename %s", skip, total_len, num_rec, basename));
+    LOG((4, "skip %d total_len %d num_rec %d basename %s", skip, total_len, num_rec, basename));
 
     /* Read each index record. These is one record for each message in
        the original GRIB1 file. */
@@ -844,7 +851,7 @@ g2c_open_index1(const char *index_file)
 					   gds_val, bms_val, bds_val, NULL, NULL, NULL)))
 	    break;
 
-	LOG((3, "b2_msg %d b2_pds %d b2_gds %d b2_bms %d b2_bds %d msglen %d version %d",
+	LOG((4, "b2_msg %d b2_pds %d b2_gds %d b2_bms %d b2_bds %d msglen %d version %d",
 	     b2_msg, b2_gds, b2_pds, b2_bms, b2_bds, msglen, version));
 	printf("b2_msg %d b2_pds %d b2_gds %d b2_bms %d b2_bds %d msglen %d version %d\n",
 	       b2_msg, b2_gds, b2_pds, b2_bms, b2_bds, msglen, version);
@@ -898,7 +905,7 @@ g2c_open_index(const char *data_file, const char *index_file, int mode,
     if (strlen(data_file) > G2C_MAX_NAME)
         return G2C_ENAMETOOLONG;
 
-    LOG((1, "g2c_open_index index_file %s", index_file));
+    LOG((2, "g2c_open_index index_file %s", index_file));
 
     /* Open the index file. */
     if (!(f = fopen(index_file, "rb")))
@@ -939,7 +946,7 @@ g2c_open_index(const char *data_file, const char *index_file, int mode,
             memcpy(time_str, long_time_str, G2C_INDEX_TIME_STR_LEN);
             time_str[G2C_INDEX_TIME_STR_LEN] = 0;
         }
-        LOG((2, "str1 %s i %d j %d k %d date_str %s time_str %s", str1, i, j, k, date_str,
+        LOG((1, "str1 %s i %d j %d k %d date_str %s time_str %s", str1, i, j, k, date_str,
              time_str));
 
         /* Read the second line of header. */
@@ -954,7 +961,7 @@ g2c_open_index(const char *data_file, const char *index_file, int mode,
             memcpy(basename, long_basename, G2C_INDEX_BASENAME_LEN);
             basename[G2C_INDEX_BASENAME_LEN] = 0;
         }
-        LOG((2, "skip %d total_len %d num_rec %d basename %s", skip, total_len, num_rec, basename));
+        LOG((1, "skip %d total_len %d num_rec %d basename %s", skip, total_len, num_rec, basename));
 
         /* Read each index record. */
         for (rec = 0; rec < num_rec; rec++)
@@ -972,7 +979,8 @@ g2c_open_index(const char *data_file, const char *index_file, int mode,
             }
 
             /* Read the index record. */
-            LOG((4, "reading index record at file position %ld", ftell(f)));
+            LOG((4, "reading index record at file position %ld, index_version %d",
+		 ftell(f), index_version));
 	    if (index_version == 1)
 	    {
 		if ((ret = g2c_start_index_record(f, G2C_FILE_READ, &reclen, &msgint, &local, &gds, &pds,
@@ -987,7 +995,7 @@ g2c_open_index(const char *data_file, const char *index_file, int mode,
 		    break;
 	    }
 
-            LOG((3, "reclen %d msg %ld local %d gds %d pds %d drs %d bms %d data %d "
+            LOG((1, "reclen %d msg %ld local %d gds %d pds %d drs %d bms %d data %d "
                  "msglen %ld version %d discipline %d fieldnum %d",
                  reclen, msg, local, gds, pds, drs, bms, data, msglen,
                  version, discipline, fieldnum));

diff --git a/src/g2cutil.c b/src/g2cutil.c
@@ -111,28 +111,28 @@ g2c_log_section1(G2C_MESSAGE_INFO_T *msg)
     /* Section 0 discipline flag. */
     if ((ret = g2c_find_desc("Code table 0.0", msg->discipline, desc)))
 	return ret;
-    LOG((2, "Discipline: %s", desc));
+    LOG((4, "Discipline: %s", desc));
 
     /* Section 1 flags. */
-    LOG((2, "Identification of originating/generating center: %d", msg->center));
-    LOG((2, "Identification of originating/generating subcenter: %d", msg->subcenter));
+    LOG((4, "Identification of originating/generating center: %d", msg->center));
+    LOG((4, "Identification of originating/generating subcenter: %d", msg->subcenter));
     if ((ret = g2c_find_desc("Code table 1.0", msg->master_version, desc)))
 	return ret;
-    LOG((2, "GRIB master tables version number: %s", desc));	
+    LOG((4, "GRIB master tables version number: %s", desc));	
     if ((ret = g2c_find_desc("Code table 1.1", msg->local_version, desc)))
 	return ret;
-    LOG((2, "Version number of GRIB local tables used to augment Master Tables: %s", desc));
+    LOG((4, "Version number of GRIB local tables used to augment Master Tables: %s", desc));
     if ((ret = g2c_find_desc("Code table 1.2", msg->sig_ref_time, desc)))
 	return ret;
-    LOG((2, "Significance of reference time: %s", desc));
-    LOG((2, "Reference time: %d/%d/%d %d:%d:%d", msg->year, msg->month, msg->day,
+    LOG((4, "Significance of reference time: %s", desc));
+    LOG((4, "Reference time: %d/%d/%d %d:%d:%d", msg->year, msg->month, msg->day,
 	 msg->hour, msg->minute, msg->second));
     if ((ret = g2c_find_desc("Code table 1.3", msg->status, desc)))
 	return ret;
-    LOG((2, "Production Status of Processed data in the GRIB message: %s", desc));
+    LOG((4, "Production Status of Processed data in the GRIB message: %s", desc));
     if ((ret = g2c_find_desc("Code table 1.4", msg->type, desc)))
 	return ret;
-    LOG((2, "Type of processed data in this GRIB message: %s", desc));
+    LOG((4, "Type of processed data in this GRIB message: %s", desc));
 
 #endif
     return G2C_NOERROR;
@@ -207,9 +207,9 @@ g2c_log_file(int g2cid)
 
 	LOG((1, "message %ld bytes_to_msg %ld bytes_in_msg %ld num_fields %d num_local %d",
 	     msg->msg_num, msg->bytes_to_msg, msg->bytes_in_msg, msg->num_fields, msg->num_local));
-        LOG((2, "sec1_len %d center %d subcenter %d master_version %d local_version %d",
+        LOG((1, "sec1_len %d center %d subcenter %d master_version %d local_version %d",
              msg->sec1_len, msg->center, msg->subcenter, msg->master_version, msg->local_version));
-        LOG((2, "sig_ref_time %d %d %d %d %d:%d:%d status %d type %d", msg->sig_ref_time, msg->year,
+        LOG((1, "sig_ref_time %d %d %d %d %d:%d:%d status %d type %d", msg->sig_ref_time, msg->year,
              msg->month, msg->day, msg->hour, msg->minute, msg->second, msg->status, msg->type));
 
 	/* If we've loaded XML tables, decode some flags. */

diff --git a/src/util.c b/src/util.c
@@ -110,10 +110,15 @@ g2_log(int severity, const char *fmt, ...)
 /**
  * Use this to set the global log level. 
  * 
- * Set it to -1 to turn off all logging. Set it
- * to 0 to show only errors, and to higher numbers to show more and
- * more logging details. If logging is not enabled when building
- * NCEPLIBS-g2c, this function will do nothing.
+ * Settings:
+ * - -1 turn off all logging.
+ * - 0 show only errors.
+ * - 1 output useful as verbose to utilities.
+ * - 2 or 3 shows some/all calls to top-level functions.
+ * - 4+ ever greater levels of detail.
+ *
+ * If logging is not enabled when building NCEPLIBS-g2c, this function
+ * will do nothing.
  *
  * @param new_level The new logging level.
  *

diff --git a/tests/run_index_tests.sh b/tests/run_index_tests.sh
@@ -10,7 +10,7 @@ echo ""
 echo "*** Running g2c_index test"
 
 # Create an index for a GRIB2 file.
-../utils/g2c_index -v data/gdaswave.t00z.wcoast.0p16.f000.grib2 gdaswave.t00z.wcoast.0p16.f000.grib2.idx
+../utils/g2c_index -v -o gdaswave.t00z.wcoast.0p16.f000.grib2.idx data/gdaswave.t00z.wcoast.0p16.f000.grib2 
 
 # Summarize the index data.
 ../utils/g2c_degrib2 -v -o gdaswave.t00z.wcoast.0p16.f000.grib2.idx.degrib2 data/gdaswave.t00z.wcoast.0p16.f000.grib2 gdaswave.t00z.wcoast.0p16.f000.grib2.idx 

diff --git a/tests/run_large_index_tests.sh b/tests/run_large_index_tests.sh
@@ -10,10 +10,10 @@ echo ""
 echo "*** Running g2c_index large file test"
 
 # Create an index for a GRIB2 file.
-../utils/g2c_index -v data/fv3lam.t00z.prslev.f000.grib2 fv3lam.t00z.prslev.f000.grib2.idx
+../utils/g2c_index -o fv3lam.t00z.prslev.f000.grib2.idx -l -v data/fv3lam.t00z.prslev.f000.grib2 
 
 # Summarize the index data.
-#../utils/g2c_degrib2 -v -o fv3lam.t00z.prslev.f000.grib2.idx.degrib2 fv3lam.t00z.prslev.f000.grib2.idx 
+../utils/g2c_degrib2 -v -o fv3lam.t00z.prslev.f000.grib2.idx.degrib2 data/fv3lam.t00z.prslev.f000.grib2 fv3lam.t00z.prslev.f000.grib2.idx 
 
 # Check against expected output.
 #diff -w fv3lam.t00z.prslev.f000.grib2.idx.degrib2 data/ref_fv3lam.t00z.prslev.f000.grib2.degrib2

diff --git a/utils/g2c_degrib2.c b/utils/g2c_degrib2.c
@@ -78,6 +78,11 @@ main(int argc, char **argv)
             break;
     }
 
+    /* Turn on logging for verbose output. This only has effect if the
+     * library was built with LOGGING=ON. */
+    if (verbose)
+	g2c_set_log_level(1);
+
     /* If we got one input file, open it. If we got two input files,
      * the second is an index file for the first. */
     if (p == 1)
@@ -87,7 +92,10 @@ main(int argc, char **argv)
 
 	/* Open the GRIB2 file. */
 	if ((ret = g2c_open(filein, G2C_NOWRITE, &g2cid)))
+	{
+	    fprintf(stderr, "Could not read file %s.\n", filein);
 	    return ret;
+	}
     }
     else if (p == 2)
     {
@@ -97,7 +105,10 @@ main(int argc, char **argv)
 
 	/* Open the GRIB2 file with index. */
 	if ((ret = g2c_open_index(filein, fileidx, G2C_NOWRITE, &g2cid)))
+	{
+	    fprintf(stderr, "Could not read file %s with index %s.\n", filein, fileidx);
 	    return ret;
+	}
     }
     else
     {
@@ -107,11 +118,17 @@ main(int argc, char **argv)
 
     /* Write the degrib2 summary. */
     if ((ret = g2c_degrib2(g2cid, fileout)))
+    {
+	fprintf(stderr, "Could not write degrib2 summary to %s.\n", fileout);
         return ret;
+    }
 
     /* Close the file. */
     if ((ret = g2c_close(g2cid)))
+    {
+	fprintf(stderr, "Error closing the file.\n");
         return ret;
+    }
 
     /* Free memory. */
     if (filein)