Inconsistency in handling data read errors in _read_data_from_dfile

[wangyinz]

Read the code below first.

mspass/python/mspasspy/db/database.py

Lines 4288 to 4324 in bf7e2f0

	if tr.stats.endtime.timestamp != mspass_object.endtime():
	message = "Inconsistent endtimes detected\n"
	message += (
	"Endtime expected from MongoDB document = {}\n".format(
	UTCDateTime(mspass_object.endtime())
	)
	)
	message += "Endtime set by obspy reader = {}\n".format(
	tr.stats.endtime
	)
	message += "Endtime is derived in mspass and should have been repaired - cannot recover this datum so it was killed"
	mspass_object.elog.log_error(
	alg, message, ErrorSeverity.Invalid
	)
	mspass_object.kill()
	# These two lines are needed to properly initialize
	# the DoubleVector before calling Trace2TimeSeries
	tr_data = tr.data.astype(
	"float64"
	) # Convert the nparray type to double, to match the DoubleVector
	mspass_object.npts = len(tr_data)
	mspass_object.data = DoubleVector(tr_data)
	# We can't use Trace2TimeSeries because we loose
	# all but miniseed metadata if we do that.
	# We do, however, need to compare post errors
	# if there is a mismatch
	if mspass_object.npts > 0:
	mspass_object.set_live()
	else:
	message = "Error during read with format={}\n".format(format)
	message += "Unable to reconstruct data vector"
	mspass_object.elog.log_error(
	alg, message, ErrorSeverity.Invalid
	)
	mspass_object.kill()

Basically, the data got killed when the endtime doesn't match. The elog message claims that such data will be killed. However, it was later being set alive because the npts is greater than 0, which is mostly true because otherwise it won't be able to calculate the endtime. I can see inside the database the corresponding elog appears to be:

{
   "_id":{
      "$oid":"6670faebf7b0b388f4b5bcd7"
   },
   "logdata":[
      {
         "job_id":{
            "$numberInt":"0"
         },
         "algorithm":"Database._read_data_from_dfile:  ",
         "badness":"ErrorSeverity.Invalid",
         "error_message":"Inconsistent endtimes detected\nEndtime expected from MongoDB document = 2011-04-07T15:17:43.975000Z\nEndtime set by obspy reader = 2011-04-07T15:17:43.975000Z\nEndtime is derived in mspass and should have been repaired - cannot recover this datum so it was killed",
         "process_id":{
            "$numberInt":"3266"
         }
      }
   ],
   "data_tag":"serial_preprocessed",
   "wf_TimeSeries_id":{
      "$oid":"6670f5c8131a86997a8e1d1e"
   }
}

Note that this record is from the earthscope2024 notebook here.

I think all we need is probably change the wording of the elog message to reflect that the error is potentially harmless. Or, we should refine the checking here such that errors within a certain threshold is acceptable (which is the case above).

[pavlis]

Good catch. How did you detect that? I see you checked in revised notebooks but is there a fix to database?

…

On Jun 17, 2024, at 11:34 PM, Ian Wang ***@***.***> wrote: This message was sent from a non-IU address. Please exercise caution when clicking links or opening attachments from external sources. Read the code below first. https://github.com/mspass-team/mspass/blob/bf7e2f05609888b56a238095ff2aa3527e304694/python/mspasspy/db/database.py#L4288-L4324 Basically, the data got killed when the endtime doesn't match. The elog message claims that such data will be killed. However, it was later being set alive because the npts is greater than 0, which is mostly true because otherwise it won't be able to calculate the endtime. I can see inside the database the corresponding elog appears to be: { "_id":{ "$oid":"6670faebf7b0b388f4b5bcd7" }, "logdata":[ { "job_id":{ "$numberInt":"0" }, "algorithm":"Database._read_data_from_dfile: ", "badness":"ErrorSeverity.Invalid", "error_message":"Inconsistent endtimes detected\nEndtime expected from MongoDB document = 2011-04-07T15:17:43.975000Z\nEndtime set by obspy reader = 2011-04-07T15:17:43.975000Z\nEndtime is derived in mspass and should have been repaired - cannot recover this datum so it was killed", "process_id":{ "$numberInt":"3266" } } ], "data_tag":"serial_preprocessed", "wf_TimeSeries_id":{ "$oid":"6670f5c8131a86997a8e1d1e" } } Note that this record is from the earthscope2024 notebook here <https://github.com/mspass-team/mspass_tutorial/blob/master/Earthscope2024/Session1.ipynb>. I think all we need is probably change the wording of the elog message to reflect that the error is potentially harmless. Or, we should refine the checking here such that errors within a certain threshold is acceptable (which is the case above). — Reply to this email directly, view it on GitHub <#549>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AABNEJ42MP7LKD6HY2GI5VDZH6TD7AVCNFSM6AAAAABJPFF7BCVHI2DSMVQWIX3LMV43ASLTON2WKOZSGM2TQOBQGU2TCMQ>. You are receiving this because you are subscribed to this thread.

[wangyinz]

I found it by looking at the records in the elog collection in the database. This mismatch error actually happened pretty frequently from that small dataset. Anyway, I don't think this needs immediate attention, but we do need to fix it. I am just opening the issue here as a bookmark.

[pavlis]

I think on the test data set it is related to an error thrown but handled on one of the files. This problem is fundamentally created by the fact we are using obspy's reader to crack miniseed files when running the read_data method of Database but the index read_data uses is created by our custom reader that only indexes the files. Since both use the same underlying miniseed library a working hypothesis is that some packets in the files have intact headers but the compressed data section of some packets have errors that make them impossible to decompress. I think obspy's reader will truncate any trace with such an error at the end of the previous packet. That would explain the behavior if my guess is correct.