Add "Validation Complete" to logging object instead of stdout

[carmeloMagna]

Describe the bug JSON Output is malformed, a spurious string "Validation complete." appears in between the JSON output.

To Reproduce Steps to reproduce the behavior: validate PDS4_file.xml -x <xsd/files> -s JSON

Obtained Output

  "title": "PDS Validation Tool Report",
  "configuration": {
    "version": "1.17.5",
    "date": "2020-01-10T17:06:28Z"
  },
  "parameters": {
    "targets": "[file:/share/CACHEDEV1_DATA/Web/MIS_DB/tmp/isa_par_sc_nominal_obs_00011_20190701.xml]",
    "userSpecifiedSchemas": "[file:/share/CACHEDEV1_DATA/Web/MIS_DB/tools/validate-1.17.5/data/xsd/PDS4_PDS_1800.xsd, file:/share/CACHEDEV1_DATA/Web/MIS_DB/tools/validate-1.17.5/data/xsd/PDS4_PDS_1500.xsd, file:/share/CACHEDEV1_DATA/Web/MIS_DB/tools/validate-1.17.5/data/xsd/PDS4_GEOM_1300.xsd, file:/share/CACHEDEV1_DATA/Web/MIS_DB/tools/validate-1.17.5/data/xsd/PDS4_PSA_LDD_1000.xsd, file:/share/CACHEDEV1_DATA/Web/MIS_DB/tools/validate-1.17.5/data/xsd/PDS4_PSA_BC_LDD_1000.xsd]",
    "userSpecifiedSchematrons": "[file:/share/CACHEDEV1_DATA/Web/MIS_DB/tools/validate-1.17.5/data/sch/PDS4_PDS_1800.sch, file:/share/CACHEDEV1_DATA/Web/MIS_DB/tools/validate-1.17.5/data/sch/PDS4_PSA_1000.sch, file:/share/CACHEDEV1_DATA/Web/MIS_DB/tools/validate-1.17.5/data/sch/PDS4_PSA_BC_1000.sch]",
    "severityLevel": "WARNING",
    "recurseDirectories": "true",
    "fileFiltersUsed": "[*.xml, *.XML]",
    "dataContentValidation": "on",
    "productLevelValidation": "on",
    "maxErrors": "100000",
    "registeredContextsFile": "/share/CACHEDEV1_DATA/Web/MIS_DB/tools/validate-1.17.5/resources/registered_context_products.json"
  },
  "productLevelValidationResults": [
    {
      "status": "FAIL",
      "label": "file:/share/CACHEDEV1_DATA/Web/MIS_DB/tmp/isa_par_sc_nominal_obs_00011_20190701.xml",
      "messages": [
        {
          "severity": "ERROR",
          "type": "error.label.schema",
          "line": 191,
          "column": 41,
          "message": "cvc-datatype-valid.1.2.1: '$orbit_start' is not a valid value for 'integer'."
        },
        {
          "severity": "ERROR",
          "type": "error.label.schema",
          "line": 191,
          "column": 41,
          "message": "cvc-type.3.1.3: The value '$orbit_start' of element 'psa:start_orbit_number' is not valid."
        },
        {
          "severity": "ERROR",
          "type": "error.label.schema",
          "line": 192,
          "column": 40,
          "message": "cvc-datatype-valid.1.2.1: '$orbit_stop' is not a valid value for 'integer'."
        },
        {
          "severity": "ERROR",
          "type": "error.label.schema",
          "line": 192,
          "column": 40,
          "message": "cvc-type.3.1.3: The value '$orbit_stop' of element 'psa:stop_orbit_number' is not valid."
        },
        {
          "severity": "ERROR",
          "type": "error.label.schema",
          "line": 218,
          "column": 24,
          "message": "cvc-complex-type.2.4.a: Invalid content was found starting with element '{\"http://pds.nasa.gov/pds4/pds/v1\":Internal_References}'. One of '{\"http://pds.nasa.gov/pds4/pds/v1\":Internal_Reference, \"http://pds.nasa.gov/pds4/pds/v1\":External_Reference}' is expected."
        },
        {
          "severity": "ERROR",
          "type": "error.label.schematron",
          "line": 186,
          "column": 38,
          "message": "The attribute psa:mission_phase_identifier must be equal to one of the following values \n            'sft-tbtv',\n            'sft2',\n            'svt1a',\n            'necp',\n            'cruise',\n            'mcp',\n            'vga1',\n            'vga2',\n            'mga1',\n            'mga2',\n            'mga3',\n            'mga4',\n            'moi',\n            'mocp',\n            'msp'."
        },
        {
          "severity": "ERROR",
          "type": "error.label.missing_file",
          "message": "URI reference does not exist: file:/share/CACHEDEV1_DATA/Web/MIS_DB/tmp/isa_par_sc_nominal_obs_00011_20190701.tab"
        },
        {
          "severity": "ERROR",
          "type": "error.label.context_ref_not_found",
          "line": 149,
          "message": "'Context product not found: urn:esa:psa:bc:context:investigation.bc"
        },
        {
          "severity": "ERROR",
          "type": "error.label.context_ref_not_found",
          "line": 160,
          "message": "'Context product not found: urn:esa:psa:bc:context:instrument_host.mpo"
        },
        {
          "severity": "ERROR",
          "type": "error.label.context_ref_not_found",
          "line": 170,
          "message": "'Context product not found: urn:esa:psa:bc:context:instrument.isa__mpo"
        },
        {
          "severity": "ERROR",
          "type": "error.label.context_ref_not_found",
          "line": 180,
          "message": "'Context product not found: urn:nasa:pds:target.MERCURY"
        }
      ],
      "fragments": [],
      "dataContents": [
        {
          "dataFile": "file:/share/CACHEDEV1_DATA/Web/MIS_DB/tmp/isa_par_sc_nominal_obs_00011_20190701.tab",
          "messages": [
            {
              "severity": "ERROR",
              "type": "error.table.bad_file_read",
              "table": 1,
              "message": "Error occurred while trying to read table: /share/CACHEDEV1_DATA/Web/MIS_DB/tmp/isa_par_sc_nominal_obs_00011_20190701.tab (No such file or directory)"
            }
          ]
        }
      ]
    }
Validation complete.

  ],
  "summary": {
    "totalErrors": 12,
    "totalWarnings": 0,
    "messageTypes": [
      {
        "messageType": "error.label.schema",
        "total": 5
      },
      {
        "messageType": "error.label.context_ref_not_found",
        "total": 4
      },
      {
        "messageType": "error.label.schematron",
        "total": 1
      },
      {
        "messageType": "error.label.missing_file",
        "total": 1
      },
      {
        "messageType": "error.table.bad_file_read",
        "total": 1
      }
    ]
  }
}```

** Version of Software Used**
1.17.5

Can you please fix this? 

Thank you

Carmelo 
IAPS/INAF  Italian National Institute for Astrophysics (INAF)

[jordanpadams]

@carmeloMagna are you parsing the output from stdout or piping to a file?

Validation complete. is going into stdout only. If you run validate with the -r flag, you can output the data to a JSON file and it will not contain that data.

 -r,--report-file <file name>            Specify the report file name. Default
                                                           is standard out.

[carmeloMagna]

Hi @jordanpadams, thank you for the suggestion.

well, I'm writing a web-based service based on the validation script for my reseach group. So, I call the validate script code using php shell_exec() function (of course sanitarizing the inputs first). So yes, actually I'm retrieving the results from stdout.

The solution you are suggesting is a little bit complicated since php does not know when the file is available. I'm actually using a work around that is to match and remove the Validation complete. statement from the output before to parse the JSON in a normal object and it works.

I think the problem has to be treated as a real bug and fixed in the future, even if several work around exist.

Kind regards and thank you again,

Carmelo

[jordanpadams]

@carmeloMagna we will add this to the list. thanks!

[jordanpadams]

@carmeloMagna we actually just pushed out a new version of validate to fix another critical bug, and it looks like this is no longer a problem in the latest version. please take a look and let me know if this version fixes your issue. https://nasa-pds-incubator.github.io/validate/

[carmeloMagna]

Dear @jordanpadams, I checked your last version 1.18.1 and the problem disappeared.

Thank you for your support! kind regards, Carmelo