Odd warehouse sample validation error "Attempt to read property "data_type" on bool"

[kazlauskis]

Uploading samples using the REST API sometimes returns 400 "data_type" validation errors. I cannot reproduce this, but you can see this in the logs. I have seen this happen for custom sample attributes smpAttr:335 and smpAttr:759.

e.g uploading

{
    "values": {
        "deleted": "f",
        "date": "1/1/2024",
        "entered_sref_system": 4326,
        "smpAttr:760": "gps",
        "smpAttr:335": "ST408149",
        "smpAttr:282": 10,
        "smpAttr:283": 50,
        "smpAttr:284": 7,
        "location_name": "Seavington Saint Michael",
        "entered_sref": "50.9309500, -2.8430200",
        "survey_id": 374,
        "smpAttr:273": 2398,
        "smpAttr:759": "16.6.1",
        "smpAttr:1139": "6.1.0",
        "input_form": "enter-app-record"
    },
    "occurrences": [
        {
            "values": {
                "deleted": "f",
                "taxa_taxon_list_id": 199384,
                "occAttr:523": 667,
                "occAttr:106": 1950
            }
        }
    ]
}

resulted in

2024-01-01 11:09:52 error Rest API request failed: HTTP 400 Bad Request.
{"smpAttr:335":"Attempt to read property \"data_type\" on bool"}

I can see in the logs the same thing happened on 2024-01-03 09:44:13.

[JimBacon]

There is also a stack trace in the log

2024-01-01 11:09:52 +00:00 --- debug: Accepted value ST408149 into field text_value for attribute smpAttr:335.
2024-01-01 11:09:52 +00:00 --- error: #2: Error converted to exception. Attempt to read property "data_type" on bool at line 58 in file /srv/sites/warehouse1.indicia.org.uk/application/libraries/Attribute_Value_ORM.php
2024-01-01 11:09:52 +00:00 --- debug: Stack trace:
    /srv/sites/warehouse1.indicia.org.uk/application/libraries/Attribute_Value_ORM.php - line 58 - indicia_error_handler
    /srv/sites/warehouse1.indicia.org.uk/application/models/sample_attribute_value.php - line 31 - attribute_validation
    /srv/sites/warehouse1.indicia.org.uk/application/libraries/MY_ORM.php - line 2295 - validate
    /srv/sites/warehouse1.indicia.org.uk/application/libraries/MY_ORM.php - line 2000 - createAttributeRecord
    /srv/sites/warehouse1.indicia.org.uk/application/libraries/MY_ORM.php - line 1072 - createAttributes
    /srv/sites/warehouse1.indicia.org.uk/application/libraries/MY_ORM.php - line 776 - inner_submit
    /srv/sites/warehouse1.indicia.org.uk/modules/rest_api/helpers/rest_crud.php - line 781 - submit
    /srv/sites/warehouse1.indicia.org.uk/modules/rest_api/helpers/rest_crud.php - line 71 - submit
    /srv/sites/warehouse1.indicia.org.uk/modules/rest_api/controllers/services/rest.php - line 3270 - create
    /srv/sites/warehouse1.indicia.org.uk/modules/rest_api/controllers/services/rest.php - line 926 - samplesPost
    Unknown file - line Unknown - __call
    /srv/sites/warehouse1.indicia.org.uk/system/core/Kohana.php - line 291 - invokeArgs
    /srv/sites/warehouse1.indicia.org.uk/system/core/Event.php - line 209 - instance
    /srv/sites/warehouse1.indicia.org.uk/system/core/Bootstrap.php - line 55 - run
    /srv/sites/warehouse1.indicia.org.uk/index.php - line 112 - require

[johnvanbreda]

I'm not sure I can see why this has happened, but I can see some small improvements in the code that might make this not occur so I'll make those changes.

[JimBacon]

Thanks John. I couldn't see how the loadAttrDef() function could return a boolean rather than an object even if there was a problem with the database query. I'm guessing it is an intermittent problem too.

[johnvanbreda]

@JimBacon neither can I, but I can code against either the cache fetch, or the database query, somehow returning a bool instead of a record, which I've done and deployed. I think that should fix it, however iRecord is giving errors on Ajax requests for Elasticsearch data at the moment which I have not seen before - this may be unrelated. I'll ask Biren as it looks a bit like a Cors problem (to reproduce, just visit the home page of iRecord).

[JimBacon]

Just an additional note, having browsed the error log further. 3 very similar records were submitted by the same person at 11:09:53. The first one logged (given sample_id = 24669339) encountered the error and the other two (24669338, 24669340) were accepted.

Very much suggests a transient problem, presumably with the database query. That would imply it could crop up anywhere so defending this particular query may be too specific.

[johnvanbreda]

The other thought I had was some sort of cache corruption. Either way I agree, there may be a problem underlying this which I've not solved. Any chance of comparing the timestamps of those samples to the PostgreSQL logs to see if there were errors there (or maybe the http error log)?

[JimBacon]

I looked in the php error logs and all I saw were a lot of long-running calls to the Elasticsearch Rest API being termnated around that time. I've no access to the database server to look at its logs at present. The http log would just show the request and the 400 response, I think.

[kazlauskis]

Checking the app logs, the first error appeared on the 21st of October. Some of the errors also return An error occurred: Attempt to read property "allow_ranges" on bool. Most of these timestamps relate to this issue: