response is null with `FormRecognizer`

agiokas-dbg commented 4 years ago

ai-form-recognizer:
1.0.0:
AWS lambda:
[ ] Node JS 12.4.0

Describe the bug I am using AWS SAM, the UI and Step functions. The AWS SAM (local execution) works absolutely fine! However when I move on the lambda to AWS it produces an error which is related to the query to azure. I've turned on DEBUG to try and figure out why I get no response. Similar lambdas I've written work absolutely fine, this is the only one that doesn't!

The actual debug output is:

2020-05-28T13:39:04.092Z    14f0d339-354b-4d8e-882b-20a4c0c4a2e4    INFO    status: notStarted
azure:ai-form-recognizer:info Request: {
  "streamResponseBody": false,
  "url": "https://validation-form-recogniser.cognitiveservices.azure.com/formrecognizer/v2.0-preview/custom/models/f0349158-3474-4f58-a798-8ce26891538b/analyzeResults/7b27bffd-cd1a-4f54-8239-d0400b6c6db7",
  "method": "GET",
  "headers": {
    "_headersMap": {
      "content-type": "application/json; charset=utf-8",
      "user-agent": "azsdk-js-ai-formrecognizer/1.0.0-preview.1 core-http/1.1.1 Node/v12.16.3 OS/(x64-Linux-4.14.165-102.205.amzn2.x86_64)",
      "x-ms-client-request-id": "0c8a9ce2-e6b0-446d-ae3a-93384a210d78",
      "ocp-apim-subscription-key": "REDACTED"
    }
  },
  "withCredentials": false,
  "timeout": 0,
  "keepAlive": true,
  "requestId": "0c8a9ce2-e6b0-446d-ae3a-93384a210d78"
}
azure:ai-form-recognizer:info Response status code: 200
azure:ai-form-recognizer:info Headers: {
  "_headersMap": {
    "apim-request-id": "REDACTED",
    "content-type": "application/json; charset=utf-8",
    "date": "Thu, 28 May 2020 13:39:09 GMT",
    "strict-transport-security": "REDACTED",
    "transfer-encoding": "chunked",
    "x-content-type-options": "REDACTED",
    "x-envoy-upstream-service-time": "REDACTED"
  }
}
2020-05-28T13:39:09.148Z    14f0d339-354b-4d8e-882b-20a4c0c4a2e4    INFO    status: notStarted
azure:ai-form-recognizer:info Request: {
  "streamResponseBody": false,
  "url": "https://validation-form-recogniser.cognitiveservices.azure.com/formrecognizer/v2.0-preview/custom/models/f0349158-3474-4f58-a798-8ce26891538b/analyzeResults/7b27bffd-cd1a-4f54-8239-d0400b6c6db7",
  "method": "GET",
  "headers": {
    "_headersMap": {
      "content-type": "application/json; charset=utf-8",
      "user-agent": "azsdk-js-ai-formrecognizer/1.0.0-preview.1 core-http/1.1.1 Node/v12.16.3 OS/(x64-Linux-4.14.165-102.205.amzn2.x86_64)",
      "x-ms-client-request-id": "8b985cf0-cbda-4d80-8f31-8f4e39745a20",
      "ocp-apim-subscription-key": "REDACTED"
    }
  },
  "withCredentials": false,
  "timeout": 0,
  "keepAlive": true,
  "requestId": "8b985cf0-cbda-4d80-8f31-8f4e39745a20"
}
azure:ai-form-recognizer:info Response status code: 200
azure:ai-form-recognizer:info Headers: {
  "_headersMap": {
    "apim-request-id": "REDACTED",
    "content-type": "application/json; charset=utf-8",
    "date": "Thu, 28 May 2020 13:39:18 GMT",
    "strict-transport-security": "REDACTED",
    "transfer-encoding": "chunked",
    "x-content-type-options": "REDACTED",
    "x-envoy-upstream-service-time": "REDACTED"
  }
}
2020-05-28T13:39:19.225Z    14f0d339-354b-4d8e-882b-20a4c0c4a2e4    INFO    TypeError: Cannot read property 'type' of null
    at toFieldValue (/var/task/node_modules/@azure/ai-form-recognizer/dist/index.js:1875:29)
    at toFieldsFromFieldValue (/var/task/node_modules/@azure/ai-form-recognizer/dist/index.js:1939:32)
    at toRecognizedForm (/var/task/node_modules/@azure/ai-form-recognizer/dist/index.js:1988:17)
    at /var/task/node_modules/@azure/ai-form-recognizer/dist/index.js:1866:69
    at Array.map (<anonymous>)
    at toRecognizeFormResultResponse (/var/task/node_modules/@azure/ai-form-recognizer/dist/index.js:1866:58)
    at FormRecognizerClient$1.<anonymous> (/var/task/node_modules/@azure/ai-form-recognizer/dist/index.js:2867:24)
    at Generator.next (<anonymous>)
    at fulfilled (/var/task/node_modules/tslib/tslib.js:110:62)
    at processTicksAndRejections (internal/process/task_queues.js:97:5)

Expected behavior

When running from SAM, I get:

sam local invoke AzureQueryFunction --event events/italian_early_query.json                                             
Invoking app.azure_query_func (nodejs12.x)                                                                                                                                                                         

Fetching lambci/lambda:nodejs12.x Docker container image.............................................................................................                                                              
Mounting /home/tons/code/typescript/aws-document-extractor/.aws-sam/build/AzureQueryFunction as /var/task:ro,delegated inside runtime container                                                                    
START RequestId: 54659ee0-7448-16ea-376f-087778129e2c Version: $LATEST                                                                                                                                             
2020-05-28T13:25:39.486Z        54659ee0-7448-16ea-376f-087778129e2c    INFO    ENDPOINT https://validation-form-recogniser.cognitiveservices.azure.com/                                                           
2020-05-28T13:25:39.489Z        54659ee0-7448-16ea-376f-087778129e2c    INFO    MODEL_UUID f0349158-3474-4f58-a798-8ce26891538b                                                                                    
2020-05-28T13:25:39.489Z        54659ee0-7448-16ea-376f-087778129e2c    INFO    FILE_PATH italian_best.pdf                                                                                                         
2020-05-28T13:25:39.489Z        54659ee0-7448-16ea-376f-087778129e2c    INFO    TMP_FILE /tmp/bdfd3d3b-d8f5-4455-b09d-80324c2a674d.pdf                                                                             
2020-05-28T13:25:39.652Z        54659ee0-7448-16ea-376f-087778129e2c    INFO    { ext: 'pdf', mime: 'application/pdf' }                                                                                            
2020-05-28T13:25:40.296Z        54659ee0-7448-16ea-376f-087778129e2c    INFO    status: notStarted                                                                                                                 
2020-05-28T13:25:40.362Z        54659ee0-7448-16ea-376f-087778129e2c    INFO    status: notStarted                                                                                                                 
2020-05-28T13:25:45.426Z        54659ee0-7448-16ea-376f-087778129e2c    INFO    status: notStarted                                                                                                                 
2020-05-28T13:25:50.507Z        54659ee0-7448-16ea-376f-087778129e2c    INFO    {                                                                                                                                  
  status: 'succeeded',                                                                                                                                                                                             
  createdOn: 2020-05-28T13:25:40.000Z,                                                                                                                                                                             
  lastModified: 2020-05-28T13:25:46.000Z,                                                                                                                                                                          
  _response: {                                                                                                                                                                                                     
    headers: HttpHeaders { _headersMap: [Object] },                                                                                                                                                                
    request: WebResource {                                                                                                                                                                                         
      streamResponseBody: false,                                                                                                                                                                                   
      url: 'https://validation-form-recogniser.cognitiveservices.azure.com/formrecognizer/v2.0-preview/custom/models/f0349158-3474-4f58-a798-8ce26891538b/analyzeResults/a24da19d-d8ad-40b2-bf59-cfde32808794',    
      method: 'GET',                                                                                                                                                                                               
      headers: [HttpHeaders],                                                                                                                                                                                      
      body: undefined,                                                                                                                                                                                             
      query: undefined,                                                                                                                                                                                            
      formData: undefined,                                                                                                                                                                                         
      withCredentials: false,                                                                                                                                                                                      
      abortSignal: undefined,                                                                                                                                                                                      
      timeout: 0,                                                                                                                                                                                                  
      onUploadProgress: undefined,                                                                                                                                                                                 
      onDownloadProgress: undefined,                                                                                                                                                                               
      proxySettings: undefined,                                                                                                                                                                                    
      keepAlive: true,                                                                                                                                                                                             
      decompressResponse: undefined,                                                                                                                                                                               
      requestId: '710e593f-67b4-4833-8292-671504aa4801',                                                                                                                                                           
      operationSpec: [Object]                                                                                                                                                                                      
    },                                                                                                                                                                                                             
    status: 200,                                                                                                                                                                                                   
    readableStreamBody: undefined,                                                                                                                                                                                 
    bodyAsText: '{"status":"succeeded","createdDateTime":"2020-05-28T13:25:40Z","lastUpdatedDateTime":"2020-05-28T13:25:46Z","analyzeResult":{"version":"2.0.0","readResults":[{"page":1,"language":"en","angle":0,
"width":8.2639,"height":11.6806,"unit":"inch"},{"page":2,"language":"en","angle":0,"width":8.2639,"height":11.6806,"unit":"inch"},{"page":3,"language":"en","angle":0,"width":8.2639,"height":11.6806,"unit":"inch"
},{"page":4,"language":"en","angle":0,"width":8.2639,"height":11.6806,"unit":"inch"}],"pageResults":[{"page":1,"tables":[]},{"page":2,"tables":[]},{"page":3,"tables":[]},{"page":4,"tables":[]}],"documentResults"
:[{"docType":"custom:form","pageRange":[1,4],"fields":{"national number":{"type":"string","valueString":"502019000019717","text":"502019000019717","page":1,"boundingBox":[3.495,8.885,4.87,8.885,4.87,9.01,3.495,9
.01],"confidence":1.0},"applicant name":{"type":"string","valueString":"Meditech Endoscopy Limited","text":"Meditech Endoscopy Limited","page":2,"boundingBox":[3.485,5.925,5.59,5.925,5.59,6.085,3.485,6.085],"con
fidence":1.0},"date":{"type":"string","valueString":"08/03/2019","text":"08/03/2019","page":1,"boundingBox":[3.785,9.355,4.6000000000000005,9.355,4.6000000000000005,9.48,3.785,9.48],"confidence":1.0},"applicant 
address":{"type":"string","valueString":"Regno Unito Chesterfield Derbyshire South Street 18 S40 IQX","text":"Regno Unito Chesterfield Derbyshire South Street 18 S40 IQX","page":2,"boundingBox":[3.48,6.825,5.205
,6.825,5.205,8.155,3.48,8.155],"confidence":1.0},"european publication":{"type":"string","valueString":"EP3206555","text":"EP3206555","page":1,"boundingBox":[4.0,9.59,4.8500000000000005,9.59,4.8500000000000005,9
.715,4.0,9.715],"confidence":1.0},"patent title":{"type":"string","valueString":"SISTEMA DI PROTEZIONE DELLA PUNTA","text":"SISTEMA DI PROTEZIONE DELLA PUNTA","page":2,"boundingBox":[3.22,2.42,6.47,2.42,6.47,2.5
45,3.22,2.545],"confidence":1.0},"applicant address (page 3)":null,"applicant name (page 3)":null}}],"errors":[]}}',                                                                                               
    parsedBody: {                                                                                                                                                                                                  
      status: 'succeeded',                                                                                                                                                                                         
      createdOn: 2020-05-28T13:25:40.000Z,                                                                                                                                                                         
      lastModified: 2020-05-28T13:25:46.000Z,                                                                                                                                                                      
      analyzeResult: [Object]                                                                                                                                                                                      
    }                                                                                                                                                                                                              
  },                                                                                                                                                                                                               
  version: '2.0.0',                                                                                                                                                                                                
  forms: [                                                                                                                                                                                                         
    {                                                                                                                                                                                                              
      formType: 'custom:form',                                                                                                                                                                                     
      pageRange: [Object],                                                                                                                                                                                         
      fields: [Object],                                                                                                                                                                                            
      pages: [Array]                                                                                                                                                                                               
    }                                                                                                                                                                                                              
  ],                                                                                                                                                                                                               
  errors: []                                                                                                                                                                                                       
}                                                                                                                                                                                                                  

{"form":"IT.UIBM.filing_receipt.print.ita","result":[{"confidence":1,"name":"national number","valueText":{"text":"502019000019717","boundingBox":[{"x":3.495,"y":8.885},{"x":4.87,"y":8.885},{"x":4.87,"y":9.01},{
"x":3.495,"y":9.01}]},"value":"502019000019717","valueType":"string"},{"confidence":1,"name":"applicant name","valueText":{"text":"Meditech Endoscopy Limited","boundingBox":[{"x":3.485,"y":5.925},{"x":5.59,"y":5
.925},{"x":5.59,"y":6.085},{"x":3.485,"y":6.085}]},"value":"Meditech Endoscopy Limited","valueType":"string"},{"confidence":1,"name":"date","valueText":{"text":"08/03/2019","boundingBox":[{"x":3.785,"y":9.355},{
"x":4.6000000000000005,"y":9.355},{"x":4.6000000000000005,"y":9.48},{"x":3.785,"y":9.48}]},"value":"08/03/2019","valueType":"string"},{"confidence":1,"name":"applicant address","valueText":{"text":"Regno Unito C
hesterfield Derbyshire South Street 18 S40 IQX","boundingBox":[{"x":3.48,"y":6.825},{"x":5.205,"y":6.825},{"x":5.205,"y":8.155},{"x":3.48,"y":8.155}]},"value":"Regno Unito Chesterfield Derbyshire South Street 18
 S40 IQX","valueType":"string"},{"confidence":1,"name":"european publication","valueText":{"text":"EP3206555","boundingBox":[{"x":4,"y":9.59},{"x":4.8500000000000005,"y":9.59},{"x":4.8500000000000005,"y":9.715},
{"x":4,"y":9.715}]},"value":"EP3206555","valueType":"string"},{"confidence":1,"name":"patent title","valueText":{"text":"SISTEMA DI PROTEZIONE DELLA PUNTA","boundingBox":[{"x":3.22,"y":2.42},{"x":6.47,"y":2.42},
{"x":6.47,"y":2.545},{"x":3.22,"y":2.545}]},"value":"SISTEMA DI PROTEZIONE DELLA PUNTA","valueType":"string"},{"name":"applicant address (page 3)"},{"name":"applicant name (page 3)"}],"endpoint":"https://validat
ion-form-recogniser.cognitiveservices.azure.com/","publisher":"azure_query_func","model_uuid":"f0349158-3474-4f58-a798-8ce26891538b","lookup":[{"type":"int","key":"national number"},{"type":"date","key":"date"},
{"type":"string","key":"european publication"},{"type":"string","key":"patent title"},{"type":"string","key":"applicant name"},{"type":"string","key":"applicant address"},{"type":"string","key":"applicant name (
page 3)"},{"type":"string","key":"applicant address (page 3)"}],"input_file":"italian_best.pdf"}                                                                                                                   
END RequestId: 54659ee0-7448-16ea-376f-087778129e2c                                                                                                                                                                
REPORT RequestId: 54659ee0-7448-16ea-376f-087778129e2c  Init Duration: 600.21 ms        Duration: 11029.12 ms   Billed Duration: 11100 ms       Memory Size: 128 MB     Max Memory Used: 68 MB

Additional context

What I see happening on the AWS lambda is that the response is null. The source code is:

const { FormRecognizerClient, AzureKeyCredential } = require("@azure/ai-form-recognizer");
const fs = require("fs");
const FileType = require('file-type');
const readChunk = require('read-chunk');
const crypto = require('crypto');
const assert = require('assert').strict;
const { v4: uuidv4 } = require('uuid');

var AWS  = require('aws-sdk');
AWS.config.update({region: 'eu-west-2'});
require("dotenv").config();

/**
 *  Acquire a file from S3 bucket after it has been classified,
 *  and knowing which form it is, call the respective form recognizer
 *  from Azure cloud, and then publish the results in message on the topic
 *
 *  @see events/belgian_upload.json as event to pass here
 */
exports.azure_query_func = async (event, context) => 
{
    const bucket     = process.env["BUCKET_NAME"];
    const api_key    = process.env["FORM_RECOGNIZER_API_KEY"];
    const endpoint   = event['extractor']['uri'];
    const model_uuid = event['extractor']['model'];
    const model_form = event['form_uid'];
    const file_path  = event.input_file;
    //
    console.log("ENDPOINT", endpoint);
    console.log("MODEL_UUID", model_uuid);
    console.log("FILE_PATH", file_path);
    //
    let rand_uid = uuidv4();
    //
    let tmp_file = "/tmp/" + rand_uid + ".pdf";
    console.log("TMP_FILE", tmp_file);
    //
    var s3 = new AWS.S3();
    var params = {Bucket: bucket, Key: file_path};
    //
    let response;
    try {
        const data = await s3.getObject(params).promise();
        assert.notEqual(data, null);
        assert.notEqual(data, undefined);
        assert.equal(data.hasOwnProperty('Body'), true);
        assert.notEqual(data.Body, undefined);
        console.log(await FileType.fromBuffer(data.Body));

        const client = new FormRecognizerClient(endpoint, new AzureKeyCredential(api_key));
        const poller = await client.beginRecognizeForms(model_uuid, data.Body, "application/pdf", 
        {
            onProgress: (state) => {
                console.log(`status: ${state.status}`);
            }
        });

        await poller.pollUntilDone();
        response = poller.getResult();
        console.log(response);
    }
    catch (error) {
        console.log(error);
    }

    if (!response) {
        throw new Error("Expecting a response!");
    }
    //
    // Return stuff to the next lambda
    //
    var retval = {};
    retval['form']       = model_form;
    retval['result']     = [];
    retval['endpoint']   = endpoint;
    retval['publisher']  = "azure_query_func";
    retval['model_uuid'] = model_uuid;
    retval['lookup']     = event.lookup;
    retval['input_file'] = event.input_file;
    //
    for (const form of response.forms || []) {
        for (const field_name in form.fields) {
            const field = form.fields[field_name];
            retval['result'].push(field);
        }
    }
    //
    return retval;
};

is there a way to get a more comprehensive error? I still don't know what is that failed!
is there a way to capture the error

Any help is greatly appreciated!

jeremymeng commented 4 years ago

@agiokas-dbg could you please give preview.2 a try? There might be some error but in preview.1 the poller doesn't throw errors.

If you are unable to use preview.2, please try the following to see whether any error is logged.

const state = poller.getOperationState();
console.log(state.error);

agiokas-dbg commented 4 years ago

@jeremymeng hi, thanks for the reply! Should I do this in the callback while it's running or after?

agiokas-dbg commented 4 years ago

I suspect there's a version miss match happening here. The actual output from the AWS lambda is:

"url": "https://validation-form-recogniser.cognitiveservices.azure.com/formrecognizer/v2.0-preview/custom/models/f0349158-3474-4f58-a798-8ce26891538b/analyze",

I added the lines you suggested, and here's the result:

START RequestId: 0adcdc26-2cb2-488f-a0f0-be8763e483c5 Version: $LATEST
2020-05-29T11:56:18.034Z    0adcdc26-2cb2-488f-a0f0-be8763e483c5    INFO    ENDPOINT https://validation-form-recogniser.cognitiveservices.azure.com/
2020-05-29T11:56:18.035Z    0adcdc26-2cb2-488f-a0f0-be8763e483c5    INFO    MODEL_UUID f0349158-3474-4f58-a798-8ce26891538b
2020-05-29T11:56:18.035Z    0adcdc26-2cb2-488f-a0f0-be8763e483c5    INFO    FILE_PATH italian_best.pdf
2020-05-29T11:56:18.035Z    0adcdc26-2cb2-488f-a0f0-be8763e483c5    INFO    BUCKET evidence-extractor-bucket
2020-05-29T11:56:18.047Z    0adcdc26-2cb2-488f-a0f0-be8763e483c5    INFO    TMP_FILE /tmp/6a206df4-e0db-489e-a99f-79e871dbd05e.pdf
2020-05-29T11:56:18.708Z    0adcdc26-2cb2-488f-a0f0-be8763e483c5    INFO    { ext: 'pdf', mime: 'application/pdf' }
2020-05-29T11:56:19.868Z    0adcdc26-2cb2-488f-a0f0-be8763e483c5    INFO    status: notStarted
2020-05-29T11:56:19.896Z    0adcdc26-2cb2-488f-a0f0-be8763e483c5    INFO    status: notStarted
2020-05-29T11:56:24.960Z    0adcdc26-2cb2-488f-a0f0-be8763e483c5    INFO    status: notStarted
2020-05-29T11:56:30.017Z    0adcdc26-2cb2-488f-a0f0-be8763e483c5    INFO    TypeError: Cannot read property 'type' of null
    at toFieldValue (/var/task/node_modules/@azure/ai-form-recognizer/dist/index.js:1875:29)
    at toFieldsFromFieldValue (/var/task/node_modules/@azure/ai-form-recognizer/dist/index.js:1939:32)
    at toRecognizedForm (/var/task/node_modules/@azure/ai-form-recognizer/dist/index.js:1988:17)
    at /var/task/node_modules/@azure/ai-form-recognizer/dist/index.js:1866:69
    at Array.map (<anonymous>)
    at toRecognizeFormResultResponse (/var/task/node_modules/@azure/ai-form-recognizer/dist/index.js:1866:58)
    at FormRecognizerClient$1.<anonymous> (/var/task/node_modules/@azure/ai-form-recognizer/dist/index.js:2867:24)
    at Generator.next (<anonymous>)
    at fulfilled (/var/task/node_modules/tslib/tslib.js:110:62)
    at processTicksAndRejections (internal/process/task_queues.js:97:5)
2020-05-29T11:56:30.028Z    0adcdc26-2cb2-488f-a0f0-be8763e483c5    ERROR   Invoke Error    {"errorType":"Error","errorMessage":"Expecting a response!","stack":["Error: Expecting a response!","    at Runtime.exports.azure_query_func [as handler] (/var/task/app.js:72:15)","    at processTicksAndRejections (internal/process/task_queues.js:97:5)"]}

agiokas-dbg commented 4 years ago

Also, I am now using 1.0.0-preview.2 and I am no longer getting this error. I suspect it was some internal mechanism?

jeremymeng commented 4 years ago

@agiokas-dbg Glad to hear that preview.2 worked fine for you. I suspect that it's the same issue that was fixed by #8703, although what puzzled me is that your original report seems to indicate that the issue didn't happen in the emulator case. Now I guess only some input documents caused the error?

agiokas-dbg commented 4 years ago

@jeremymeng The same document is when run locally (SAM) worked, but failed on AWS. I thought it had to do with time-outs, but I suspect it may have to do with Unicode encoding? I honestly don't know because I've done about 16 different form models on Azure and this is the only one with this problem.

jeremymeng commented 4 years ago

Is it possible for you to share the document that was causing problem?

agiokas-dbg commented 4 years ago

Hi @jeremymeng Yes I can, I've also run into another document that seems to cause the same problem. I'm getting back no response.

But when I try the dockerized UI tool(mcr.microsoft.com/azure-cognitive-services/custom-form/labeltool) and I use it there it seems to work fine! When I invoke the npm API it seems not to return a response. Let me know if you want the OCR and LABELS jsons. The file is attached below:

finish_early.pdf

jeremymeng commented 4 years ago

Thanks! I will have a look at this document.

agiokas-dbg commented 4 years ago

Thanks Jeremy. It's still the case where the UI labeltool works fine, but I'm getting null responses.

jeremymeng commented 4 years ago

@agiokas-dbg I want to ensure that I understand it thoroughly:

you use the dockerized label tool to label sample forms, train a custom model, and analyze the document finish_early.pdf. It all worked fine there.
when using the JS SDK beginRecognizeForms() on finish_early.pdf a. Locally in AWS SAM environment it works fine too b. in AWS it failed with a null response
The issue happened with 1.0.0-preview.1
The issue does not happen with 1.0.0-preview.2

Please let me know if any of the above isn't right.

I tested the document but didn't see any thing unusual. Of course I don't have your custom model or training data to test the custom form recognition. In the case if preview.2 didn't work for you then I might need those to investigate further.

Thank you!

agiokas-dbg commented 4 years ago

Hi @jeremymeng I think you can close this issue. I tried it again today, first with SAM locally, then invoking the AWS step function code and it seems to work now. I suspect I had the older version active in one of my apps/lambdas. The newer one seems to have fixed it!

jeremymeng commented 4 years ago

Sounds good. Thanks for testing it.

Azure / azure-sdk-for-js

response is null with `FormRecognizer` #9153