404 error on model.xml

delcroip · February 9, 2023, 8:19am

Hi,

I am trying to have some form with card/context, the form was uploaded successfully, the property file is applied properly but when I want to start the form it fails because, I suspect, there is a 404 error for 2 resources (the form is called pev_enfant, not other errors before):

/medic/form%3Apev_enfant/model.xml
/medic/form%3Apev_enfant/form.html

{"error":"not_found","reason":"Document is missing attachment"}

I am using 1.17 pyxform-medic and latest cht-conf

I tried to rebuild the targets.js and tasks.js (exporting empty list) and build the app_settings but it did not change anything

I am really puzzled on what is going on, does someone have any idea ?

Br

gareth · February 9, 2023, 8:08pm

Hi @delcroip ,

When the CLI uploads the form it only uploads the Enketo xml file. When the API service on the server detects the upload, it processes the xml file and generates the model.xml and form.html files and saves them on the document too. Then the phone syncs the doc with all three attachments and stores it locally. My guess is that there’s something going wrong in the generation stage.

Firstly, check your api logs around the time the form was uploaded and you should see it generating the files. My guess is that there’s an error in your form and it’s failing the generation stage, in which case you should see an error in the log.

If there are no errors, then check in couchdb for a doc with id form:pev_enfant and see if the attachments are there. If they are, then there’s a problem syncing to the phone. Try wiping the device and replicating again to get fresh copies of the forms and see if that fixes it.

delcroip · February 10, 2023, 8:29am

Thank you @gareth

I only found the docker api logs, is there other logs in CHT 4 ?

REQ ce878b7f-bb18-4ac9-a091-b9c595b98a89 51.154.169.129 medic GET /medic/form%3Apev_enfant? HTTP/1.0
RES ce878b7f-bb18-4ac9-a091-b9c595b98a89 51.154.169.129 medic GET /medic/form%3Apev_enfant? HTTP/1.0 200 617 9.147 ms
REQ 4665b57d-e64d-474d-99d9-d819e1f53af5 51.154.169.129 medic GET /medic/form%3Apev_enfant/xml HTTP/1.0
RES 4665b57d-e64d-474d-99d9-d819e1f53af5 51.154.169.129 medic GET /medic/form%3Apev_enfant/xml HTTP/1.0 200 10157 8.204 ms
REQ 2e65cfcb-f490-47c8-8c14-42e3aa301aea 51.154.169.129 - GET /medic/_design/medic-client/_view/doc_by_type?include_docs=true&key=%5B%22form%22%5D HTTP/1.0
REQ ce7588d7-0e08-4b00-8278-da0c16e06c65 51.154.169.129 medic GET /medic/form%3Apev_enfant? HTTP/1.0
RES ce7588d7-0e08-4b00-8278-da0c16e06c65 51.154.169.129 medic GET /medic/form%3Apev_enfant? HTTP/1.0 200 617 10.365 ms

I looked in the db and I say only the XML attachment

	{
  "_id": "form:pev_enfant",
  "_rev": "22-f90fe3afd7fc6d04a2bfb3402c3f50cc",
  "type": "form",
  "internalId": "pev_enfant",
  "xmlVersion": {
    "time": 1676016837604,
    "sha256": "99fdfb67ba47ab0914f05354c543e5fb8fd080a2f89f37473e6d79b0b5b0a73d"
  },
  "title": [
    {
      "locale": "en",
      "content": "Immunization Visit"
    },
    {
      "locale": "fr",
      "content": "PEV enfant"
    }
  ],
  "context": {
    "person": true,
    "place": false,
    "expression": "contact.type === 'person' && (!contact.date_of_birth || ageInYears(contact) <= 12)"
  },
  "icon": "immunization",
  "_attachments": {
    "xml": {
      "content_type": "application/xml",
      "revpos": 22,
      "digest": "md5-sReo+Q6VR/caO7wRR6apdQ==",
      "length": 117071,
      "stub": true
    }
  }
}

diana · February 10, 2023, 12:41pm

Hi @delcroip

It appears that api fails to generate the model and html for this form.
Could you please try to upload the form again and check API logs immediately after upload?

Thanks!

delcroip · February 13, 2023, 7:47am

Thanks for the answer,

I did it several time but I failed to find the API log (but the http log above), I looked in the container for any file called “*.log” but found only 1 irrelevant occurrence

I run it again to be on the safe side :

only 200 and 201 so it looks good

2023-02-13 07:40:53 DEBUG: Checking for a configured outgoing message service 
REQ a30c8004-0677-46bc-a15c-d51c33461194 192.43.192.209 medic GET /medic/ HTTP/1.0
RES a30c8004-0677-46bc-a15c-d51c33461194 192.43.192.209 medic GET /medic/ HTTP/1.0 200 826 9.750 ms
REQ 8f8ae6da-3713-4345-bb6c-a2a46854ba42 192.43.192.209 medic GET /api/deploy-info HTTP/1.0
RES 8f8ae6da-3713-4345-bb6c-a2a46854ba42 192.43.192.209 medic GET /api/deploy-info HTTP/1.0 200 62 5.256 ms
REQ cc93ede5-72f7-474b-9c6a-74d1ba10cea5 192.43.192.209 medic POST /api/v1/forms/validate HTTP/1.0
RES cc93ede5-72f7-474b-9c6a-74d1ba10cea5 192.43.192.209 medic POST /api/v1/forms/validate HTTP/1.0 200 11 16933.679 ms
REQ fc74ef39-c9f1-4908-a17c-d67265e7b9d6 192.43.192.209 medic POST /api/v1/forms/validate HTTP/1.0
RES fc74ef39-c9f1-4908-a17c-d67265e7b9d6 192.43.192.209 medic POST /api/v1/forms/validate HTTP/1.0 200 11 372.248 ms
REQ 4d242016-4d95-4480-a038-a2fed5bd0fe9 192.43.192.209 medic GET /medic/ HTTP/1.0
RES 4d242016-4d95-4480-a038-a2fed5bd0fe9 192.43.192.209 medic GET /medic/ HTTP/1.0 200 831 9.251 ms
REQ 56b3aedf-d0ef-4894-894d-1543f6e1e52d 192.43.192.209 medic GET /medic/form%3Aadult? HTTP/1.0
RES 56b3aedf-d0ef-4894-894d-1543f6e1e52d 192.43.192.209 medic GET /medic/form%3Aadult? HTTP/1.0 200 - 8.236 ms
REQ 2fb08a2f-5417-40ce-a481-7858ee51ef79 192.43.192.209 medic GET /medic/form%3Aadult/xml HTTP/1.0
RES 2fb08a2f-5417-40ce-a481-7858ee51ef79 192.43.192.209 medic GET /medic/form%3Aadult/xml HTTP/1.0 200 112279 9.451 ms
REQ 6993f264-171f-4537-b934-60186f7648a8 192.43.192.209 medic GET /medic/form%3Aadult? HTTP/1.0
RES 6993f264-171f-4537-b934-60186f7648a8 192.43.192.209 medic GET /medic/form%3Aadult? HTTP/1.0 200 - 6.989 ms
REQ 82b984f8-397c-4509-a721-69df92a8cbb9 192.43.192.209 medic PUT /medic/form%3Aadult HTTP/1.0
RES 82b984f8-397c-4509-a721-69df92a8cbb9 192.43.192.209 medic PUT /medic/form%3Aadult HTTP/1.0 201 74 329.277 ms
REQ d6b64d50-0b9a-4775-aeb4-aaadec7b6dd2 192.43.192.209 medic GET /medic/form%3Apev_enfant? HTTP/1.0
RES d6b64d50-0b9a-4775-aeb4-aaadec7b6dd2 192.43.192.209 medic GET /medic/form%3Apev_enfant? HTTP/1.0 200 617 7.260 ms
REQ eac8a72d-11fd-4f8b-af8b-88fad18d9c97 192.43.192.209 medic GET /medic/form%3Apev_enfant/xml HTTP/1.0
RES eac8a72d-11fd-4f8b-af8b-88fad18d9c97 192.43.192.209 medic GET /medic/form%3Apev_enfant/xml HTTP/1.0 200 10173 6.880 ms
REQ 38d1ca83-3e56-4c64-8c72-38dcb502d43b 192.43.192.209 medic GET /medic/form%3Apev_enfant? HTTP/1.0
RES 38d1ca83-3e56-4c64-8c72-38dcb502d43b 192.43.192.209 medic GET /medic/form%3Apev_enfant? HTTP/1.0 200 617 7.493 ms
REQ 27d3b508-be0e-4f2f-a8a7-85609eae8d67 192.43.192.209 medic PUT /medic/form%3Apev_enfant HTTP/1.0
RES 27d3b508-be0e-4f2f-a8a7-85609eae8d67 192.43.192.209 medic PUT /medic/form%3Apev_enfant HTTP/1.0 201 79 35.332 ms

I check again and same error

Can it be related to missing dependency ?
How can I have more logs ?
What those files should contain ? are they related to a specific part/feature of the form that I could double check ?

thanks in advance

diana · February 13, 2023, 9:26am

Hi @delcroip

As @gareth said above:

From your log I can clearly see the PUT that uploads the form to the database:

delcroip:

REQ 27d3b508-be0e-4f2f-a8a7-85609eae8d67 192.43.192.209 medic PUT /medic/form%3Apev_enfant HTTP/1.0
RES 27d3b508-be0e-4f2f-a8a7-85609eae8d67 192.43.192.209 medic PUT /medic/form%3Apev_enfant HTTP/1.0 201 79 35.332 ms

And would expect to see something like this

Detected form change for form:pev_enfant
Detected form change - generating attachments
Updating form with ID form:pev_enfant

in the logs as the change gets processed.

Are you seeing anything that looks like this at all? You should see this in the API log.

delcroip · February 13, 2023, 10:46am

Hi @diana

I upgraded to CHT 4.1 but I don’t see the lines you mentioned.

I guess this is the part you are referring to:

github.com

medic/cht-core/blob/b190bc999b75a90c0f3a217804c1041368505d58/api/src/services/config-watcher.js#L101


      
              .then(() => logger.debug('Settings updated'));
          };
          
          
const handleTranslationsChange = () => {
            logger.info('Detected translations change - reloading');
            return loadTranslations()
              .then(() => initTransitionLib())
              .then(() => updateServiceWorker());
          };
          
          
const handleFormChange = (change) => {
            logger.info('Detected form change for', change.id);
            if (change.deleted) {
              return Promise.resolve();
            }
            logger.info('Detected form change - generating attachments');
            return generateXform.update(change.id).catch(err => {
              logger.error('Failed to update xform: %o', err);
            });
          };

I will try to have a look, I hope I can “rebuild” (to troubleshoot) the core within the api container

br

delcroip · February 13, 2023, 12:09pm

@diana thank you, your reply helped me “solve” my issue: this code is called upon start of the app so I restarted the container and I got that in the log:

2023-02-13 12:05:25 INFO: Service worker generated successfully 
2023-02-13 12:05:25 INFO: Service worker generated successfully 
2023-02-13 12:05:25 INFO: Updating xforms… 
2023-02-13 12:05:26 DEBUG: Generating html and xml model for enketo form "form:adult" 
2023-02-13 12:05:43 DEBUG: Generating html and xml model for enketo form "form:adult_v26" 
2023-02-13 12:05:57 DEBUG: Generating html and xml model for enketo form "form:contact:clinic:create" 
2023-02-13 12:05:57 DEBUG: Generating html and xml model for enketo form "form:contact:clinic:edit" 
2023-02-13 12:05:57 DEBUG: Generating html and xml model for enketo form "form:contact:district_hospital:create" 
2023-02-13 12:05:57 DEBUG: Generating html and xml model for enketo form "form:contact:district_hospital:edit" 
2023-02-13 12:05:57 DEBUG: Generating html and xml model for enketo form "form:contact:health_center:create" 
2023-02-13 12:05:57 DEBUG: Generating html and xml model for enketo form "form:contact:health_center:edit" 
2023-02-13 12:05:58 DEBUG: Generating html and xml model for enketo form "form:contact:person:create" 
2023-02-13 12:05:58 DEBUG: Generating html and xml model for enketo form "form:contact:person:edit" 
2023-02-13 12:05:58 DEBUG: Generating html and xml model for enketo form "form:death_report" 
2023-02-13 12:05:58 DEBUG: Generating html and xml model for enketo form "form:delivery" 
2023-02-13 12:05:58 DEBUG: Generating html and xml model for enketo form "form:pev_enfant" 
2023-02-13 12:05:58 DEBUG: Generating html and xml model for enketo form "form:pnc_danger_sign_follow_up_baby" 
2023-02-13 12:05:58 DEBUG: Generating html and xml model for enketo form "form:pnc_danger_sign_follow_up_mother" 
2023-02-13 12:05:58 DEBUG: Generating html and xml model for enketo form "form:pregnancy" 
2023-02-13 12:05:59 DEBUG: Generating html and xml model for enketo form "form:pregnancy_danger_sign" 
2023-02-13 12:05:59 DEBUG: Generating html and xml model for enketo form "form:pregnancy_danger_sign_follow_up" 
2023-02-13 12:05:59 DEBUG: Generating html and xml model for enketo form "form:pregnancy_facility_visit_reminder" 
2023-02-13 12:05:59 DEBUG: Generating html and xml model for enketo form "form:pregnancy_home_visit" 
2023-02-13 12:05:59 DEBUG: Generating html and xml model for enketo form "form:undo_death_report" 
2023-02-13 12:05:59 INFO: Updating 0 enketo forms 
2023-02-13 12:05:59 INFO: xforms updated successfully

the app also work, I don’t know the root cause but as long as I have a workaround I am happy

best regards

diana · February 13, 2023, 12:12pm

Hi @delcroip

Can you please try to upload the form again and see if API picks it up, and re-generates the attachments?

I am very invested in finding the root cause, since this can produce all manner of problems in production.
Do you by any chance have access to the old container logs (pre restart)? I’d be interested in a full dump, if you’d be keen to share.

Thanks a lot!

delcroip · February 13, 2023, 12:17pm

it does

2023-02-13 12:16:24 INFO: Detected form change - generating attachments 
2023-02-13 12:16:24 DEBUG: Generating html and xml model for enketo form "form:pev_enfant"

so not even a workaround anymore

diana · February 13, 2023, 12:18pm

Great, so it was some sort of error that one time.

delcroip · February 13, 2023, 12:20pm

Do you by any chance have access to the old container logs (pre restart)? I’d be interested in a full dump, if you’d be keen to share.

unfortunately no, but if this issue happens again with new forms be sure I will

br

kenn · April 7, 2023, 4:22pm

A second instance of this problem has been reported and it is now tracked as an open issue in cht-core 4.1 API Changes watcher skips changes - or becomes blocked · Issue #8173 · medic/cht-core · GitHub