Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

bug: SQL TIME columns causing jsonschema ValidationError Failed validating 'format': 'time' #1457

Closed
1 task
BuzzCutNorman opened this issue Feb 24, 2023 · 15 comments · Fixed by #2136
Closed
1 task

bug: SQL TIME columns causing jsonschema ValidationError Failed validating 'format': 'time' #1457

BuzzCutNorman opened this issue Feb 24, 2023 · 15 comments · Fixed by #2136
Assignees
@edgarrmondragon
Labels
kind/Bug Something isn't working valuestream/SDK

Comments

@BuzzCutNorman
Copy link
Contributor

Singer SDK Version

0.19.0

Is this a regression?

  • Yes

Python Version

3.9

Bug scope

Taps (catalog, state, etc.)

Operating System

Windows

Description

Error Info

Issue with TIME columns returning time format which is not passing JSON schema validation when sent to a target. This error was found running meltano run tap-mssql target-mssql when the tap is reading from the testdata database table TestTable. The column TestColumn1 which is a MS SQL data type of TIME is the offending column.

2023-02-24T19:45:25.219042Z [info     ]     raise error                cmd_type=elb consumer=True name=target-mssql producer=False stdio=stderr string_id=target-mssql
2023-02-24T19:45:25.219042Z [info     ] jsonschema.exceptions.ValidationError: '20:20:39.001000' is not a 'time' cmd_type=elb consumer=True name=target-mssql producer=False stdio=stderr string_id=target-mssql
2023-02-24T19:45:25.234666Z [info     ]                                cmd_type=elb consumer=True name=target-mssql producer=False stdio=stderr string_id=target-mssql
2023-02-24T19:45:25.234666Z [info     ] Failed validating 'format' in schema['properties']['TestColumn1']: cmd_type=elb consumer=True name=target-mssql producer=False stdio=stderr string_id=target-mssql
2023-02-24T19:45:25.234666Z [info     ]     {'format': 'time', 'type': ['string', 'null']} cmd_type=elb consumer=True name=target-mssql producer=False stdio=stderr string_id=target-mssql
2023-02-24T19:45:25.234666Z [info     ]                                cmd_type=elb consumer=True name=target-mssql producer=False stdio=stderr string_id=target-mssql
2023-02-24T19:45:25.234666Z [info     ] On instance['TestColumn1']:    cmd_type=elb consumer=True name=target-mssql producer=False stdio=stderr string_id=target-mssql
2023-02-24T19:45:25.234666Z [info     ]     '20:20:39.001000'          cmd_type=elb consumer=True name=target-mssql producer=False stdio=stderr string_id=target-mssql
2023-02-24T19:45:25.265917Z [error    ] Loader failed
2023-02-24T19:45:25.265917Z [error    ] Block run completed.           block_type=ExtractLoadBlocks err=RunnerError('Loader failed') exit_codes={<PluginType.LOADERS: 'loaders'>: 1} set_number=0 success=False

The TestTable was created with the following script. It contains only one row and one column.

use [testdata]
go
/*********************************
Create the simple test table
in an MSSQL database
*********************************/
DROP TABLE IF EXISTS [TestTable];
CREATE TABLE TestTable (
    Id int IDENTITY(1,1) PRIMARY KEY,
    TestColumn1 TIME
);
go
/*********************************
Insert some test data into the
test table
*********************************/
INSERT INTO [testdata].[dbo].[TestTable]
           ([TestColumn1])
     VALUES
           ('20:20:39.001')
;

findings

If I edit the value in the TestColumn1 to be '20:20:39' validation passes. I also ran into this issue when generating batch messages. The fix I chose to resolve the issue for batch message was to extend the default JSONEncoder used by json.dump() with the following code

        # Time in ISO format truncated to the second to pass
        # json-schema validation
        if isinstance(obj, datetime.time):
            return obj.isoformat(timespec='seconds')

I attempted to overload the _conform_primitive_property method but did not successfully accomplish a working overload.

There is a little more info in the issue I raised in the buzzcutnorman--tap-mssql repository.
BuzzCutNorman/tap-mssql#25

Code

def _conform_primitive_property(elem: Any, property_schema: dict) -> Any:
    """Converts a primitive (i.e. not object or array) to a json compatible type."""
    
    ...
    
    elif isinstance(elem, datetime.time):
        return str(elem)
    
    ...
@BuzzCutNorman BuzzCutNorman added kind/Bug Something isn't working valuestream/SDK labels Feb 24, 2023
@edgarrmondragon
Copy link
Collaborator

edgarrmondragon commented Feb 24, 2023 •
edited
Loading

@BuzzCutNorman I think the jsonschema library is at fault here, since according to RFC 3339, "20:20:39.001000" is a valid time string, and I've confirmed with https://www.jsonschemavalidator.net/s/cfbPNcbp.

EDIT: "20:20:39.001000" is not a valid time since it's missing the time-offset component, e.g. "20:20:39.001000+00:00" or "20:20:39.001000Z". In fact "20:20:39" also fails validation in my testing:

$ check-jsonschema --schemafile <(echo '{"type":"string","format":"time"}') <(echo '"20:20:39.001000"')
Schema validation errors were encountered.
  /dev/fd/12::$: '20:20:39.001000' is not a 'time'

$ check-jsonschema --schemafile <(echo '{"type":"string","format":"time"}') <(echo '"20:20:39"')
Schema validation errors were encountered.
  /dev/fd/12::$: '20:20:39' is not a 'time'

$ check-jsonschema --schemafile <(echo '{"type":"string","format":"time"}') <(echo '"20:20:39.001000+00:00"')
ok -- validation done

$ check-jsonschema --schemafile <(echo '{"type":"string","format":"time"}') <(echo '"20:20:39.001000Z"')
ok -- validation done

@BuzzCutNorman
Copy link
Contributor Author

BuzzCutNorman commented Feb 24, 2023 •
edited
Loading

@edgarrmondragon Thank you for the very handy command and site for validating JSON Schema. I just tired adding the +00:00 and Z via the _conform_primitive_property and got the following.

    elif isinstance(elem, datetime.time):
        return str(elem) + "+00:00"

2023-02-24T22:35:21.544793Z [info     ]     raise error                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T22:35:21.544793Z [info     ] jsonschema.exceptions.ValidationError: '20:20:39.001000+00:00' is not a 'time' cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T22:35:21.544793Z [info     ]                                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T22:35:21.544793Z [info     ] Failed validating 'format' in schema['properties']['TestColumn1']: cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T22:35:21.544793Z [info     ]     {'format': 'time', 'type': ['string', 'null']} cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T22:35:21.544793Z [info     ]                                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T22:35:21.560419Z [info     ] On instance['TestColumn1']:    cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T22:35:21.560419Z [info     ]     '20:20:39.001000+00:00'    cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T22:35:21.591667Z [error    ] Loader failed
2023-02-24T22:35:21.591667Z [error    ] Block run completed.           block_type=ExtractLoadBlocks err=RunnerError('Loader failed') exit_codes={<PluginType.LOADERS: 'loa

    elif isinstance(elem, datetime.time):
        return str(elem) + "Z"

2023-02-24T22:36:15.478479Z [info     ]     raise error                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T22:36:15.478479Z [info     ] jsonschema.exceptions.ValidationError: '20:20:39.001000Z' is not a 'time' cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T22:36:15.478479Z [info     ]                                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T22:36:15.478479Z [info     ] Failed validating 'format' in schema['properties']['TestColumn1']: cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T22:36:15.494101Z [info     ]     {'format': 'time', 'type': ['string', 'null']} cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T22:36:15.494101Z [info     ]                                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T22:36:15.494101Z [info     ] On instance['TestColumn1']:    cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T22:36:15.494101Z [info     ]     '20:20:39.001000Z'         cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T22:36:15.540981Z [error    ] Loader failed
2023-02-24T22:36:15.556602Z [error    ] Block run completed.

@edgarrmondragon
Copy link
Collaborator

@BuzzCutNorman hmm it may have to do with the version of the jsonschema library. Which target-postgres are you testing with?

@BuzzCutNorman
Copy link
Contributor Author

@edgarrmondragon I am using BuzzCutNorman target-mssql and target-postgres. I will give MeltanoLabs target-postgres a try and see if I get the same result.

@BuzzCutNorman
Copy link
Contributor Author

@edgarrmondragon just installed the MeltanoLabs target-postgres and got the same results.

2023-02-24T23:28:40.069623Z [info     ]     raise error                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T23:28:40.069623Z [info     ] jsonschema.exceptions.ValidationError: '20:20:39.001000' is not a 'time' cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T23:28:40.085245Z [info     ]                                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T23:28:40.085245Z [info     ] Failed validating 'format' in schema['properties']['TestColumn1']: cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T23:28:40.085245Z [info     ]     {'format': 'time', 'type': ['string', 'null']} cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T23:28:40.085245Z [info     ]                                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T23:28:40.085245Z [info     ] On instance['TestColumn1']:    cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T23:28:40.085245Z [info     ]     '20:20:39.001000'          cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T23:28:40.116497Z [error    ] Loader failed
2023-02-24T23:28:40.116497Z [error    ] Block run completed.           block_type=ExtractLoadBlocks err=RunnerError('Loader failed') exit_codes={<PluginType.LOADERS: 'loaders'>: 1} set_number=0 success=False

2023-02-24T23:31:14.311363Z [info     ]     raise error                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T23:31:14.311363Z [info     ] jsonschema.exceptions.ValidationError: '20:20:39.001000+00:00' is not a 'time' cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T23:31:14.311363Z [info     ]                                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T23:31:14.311363Z [info     ] Failed validating 'format' in schema['properties']['TestColumn1']: cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T23:31:14.311363Z [info     ]     {'format': 'time', 'type': ['string', 'null']} cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T23:31:14.326993Z [info     ]                                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T23:31:14.326993Z [info     ] On instance['TestColumn1']:    cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T23:31:14.326993Z [info     ]     '20:20:39.001000+00:00'    cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T23:31:14.373867Z [error    ] Loader failed
2023-02-24T23:31:14.389488Z [error    ] Block run completed.           block_type=ExtractLoadBlocks err=RunnerError('Loader failed') exit_codes={<PluginType.LOADERS: 'loaders'>: 1} set_number=0 success=False

2023-02-24T23:31:34.893830Z [info     ]     raise error                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T23:31:34.893830Z [info     ] jsonschema.exceptions.ValidationError: '20:20:39.001000Z' is not a 'time' cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T23:31:34.893830Z [info     ]                                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T23:31:34.893830Z [info     ] Failed validating 'format' in schema['properties']['TestColumn1']: cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T23:31:34.893830Z [info     ]     {'format': 'time', 'type': ['string', 'null']} cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T23:31:34.893830Z [info     ]                                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T23:31:34.909454Z [info     ] On instance['TestColumn1']:    cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T23:31:34.909454Z [info     ]     '20:20:39.001000Z'         cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-24T23:31:34.940704Z [error    ] Loader failed
2023-02-24T23:31:34.940704Z [error    ] Block run completed.           block_type=ExtractLoadBlocks err=RunnerError('Loader failed') exit_codes={<PluginType.LOADERS: 'loaders'>: 1} set_number=0 success=False

@edgarrmondragon
Copy link
Collaborator

edgarrmondragon commented Feb 24, 2023 •
edited
Loading

@BuzzCutNorman Ok I think I know what's going on. I was testing schemas with the jsonschema[format] extra, which enables this code path:

https://github.com/python-jsonschema/jsonschema/blob/6b749cfa2f47d4dd9ee74f8e01fa4fc0f8f10df6/jsonschema/_format.py#L364-L381

with suppress(ImportError):
    from rfc3339_validator import validate_rfc3339

    @_checks_drafts(name="date-time")
    def is_datetime(instance: object) -> bool:
        if not isinstance(instance, str):
            return True
        return validate_rfc3339(instance.upper())

    @_checks_drafts(
        draft7="time",
        draft201909="time",
        draft202012="time",
    )
    def is_time(instance: object) -> bool:
        if not isinstance(instance, str):
            return True
        return is_datetime("1970-01-01T" + instance)

but without the extras, only a naive check is performed:

https://github.com/python-jsonschema/jsonschema/blob/6b749cfa2f47d4dd9ee74f8e01fa4fc0f8f10df6/jsonschema/_format.py#L404-L408

@_checks_drafts(draft3="time", raises=ValueError)
def is_draft3_time(instance: object) -> bool:
    if not isinstance(instance, str):
        return True
    return bool(datetime.datetime.strptime(instance, "%H:%M:%S"))

The latter is what's causing validation errors for you.

So, can you try installing jsonschema[format] in the same environment as target-postgres? If you're using Meltano, then

pip_url: git+https://github.com/MeltanoLabs/target-postgres.git jsonschema[format]

should do it.

@edgarrmondragon edgarrmondragon mentioned this issue Feb 24, 2023
Open
@BuzzCutNorman
Copy link
Contributor Author

@edgarrmondragon I added pip_url: git+https://github.com/MeltanoLabs/target-postgres.git jsonschema[format] as requested and did a meltano install --clean. I get the same error on all three version like before. I checked the pip list for the target-postgres venv and I see:

jsonschema                  4.17.3

@edgarrmondragon
Copy link
Collaborator

@BuzzCutNorman We're looking for rfc3339-validator in the loader venv. I do see it when I install with the pip URL above

With original pip URL 
$ .meltano/loaders/target-postgres/venv/bin/pip list
Package                     Version
--------------------------- --------------------
appdirs                     1.4.4
attrs                       22.2.0
backoff                     2.2.1
certifi                     2022.12.7
cffi                        1.15.1
charset-normalizer          3.0.1
click                       8.1.3
cryptography                39.0.1
decorator                   5.1.1
fs                          2.4.16
greenlet                    2.0.2
idna                        3.4
inflection                  0.5.1
joblib                      1.2.0
jsonpath-ng                 1.5.3
jsonschema                  4.17.3
meltanolabs-target-postgres 0.0.4.post10+1859883
memoization                 0.4.0
pendulum                    2.1.2
pip                         23.0.1
ply                         3.11
psycopg2-binary             2.9.5
pycparser                   2.21
PyJWT                       2.6.0
pyrsistent                  0.19.3
python-dateutil             2.8.2
python-dotenv               0.21.1
pytz                        2022.7.1
pytzdata                    2020.1
PyYAML                      6.0
requests                    2.28.2
setuptools                  57.5.0
simplejson                  3.18.3
singer-sdk                  0.19.0
six                         1.16.0
SQLAlchemy                  1.4.46
typing_extensions           4.5.0
urllib3                     1.26.14
wheel                       0.38.4
With jsonschema extras 
$ .meltano/loaders/target-postgres/venv/bin/pip list
Package                     Version
--------------------------- --------------------
appdirs                     1.4.4
arrow                       1.2.3
attrs                       22.2.0
backoff                     2.2.1
certifi                     2022.12.7
cffi                        1.15.1
charset-normalizer          3.0.1
click                       8.1.3
cryptography                39.0.1
decorator                   5.1.1
fqdn                        1.5.1
fs                          2.4.16
greenlet                    2.0.2
idna                        3.4
inflection                  0.5.1
isoduration                 20.11.0
joblib                      1.2.0
jsonpath-ng                 1.5.3
jsonpointer                 2.3
jsonschema                  4.17.3
meltanolabs-target-postgres 0.0.4.post10+1859883
memoization                 0.4.0
pendulum                    2.1.2
pip                         23.0.1
ply                         3.11
psycopg2-binary             2.9.5
pycparser                   2.21
PyJWT                       2.6.0
pyrsistent                  0.19.3
python-dateutil             2.8.2
python-dotenv               0.21.1
pytz                        2022.7.1
pytzdata                    2020.1
PyYAML                      6.0
requests                    2.28.2
rfc3339-validator           0.1.4
rfc3987                     1.3.8
setuptools                  57.5.0
simplejson                  3.18.3
singer-sdk                  0.19.0
six                         1.16.0
SQLAlchemy                  1.4.46
typing_extensions           4.5.0
uri-template                1.2.0
urllib3                     1.26.14
webcolors                   1.12
wheel                       0.38.4

@BuzzCutNorman
Copy link
Contributor Author

BuzzCutNorman commented Feb 25, 2023 •
edited
Loading

@edgarrmondragon I can confirm that the rfc2229-vaidator is present in the target-postgres venv. I still see the errors for all three versions of time. I did notice that at the top of the trace back it says the validator is is_draft3_time . I have added all three full trace backs below.

target-postgres pip list 

(venv) PS C:\development\projects\dev-sql-dataype> pip list
Package                     Version
--------------------------- --------------------
appdirs                     1.4.4
arrow                       1.2.3
attrs                       22.2.0
backoff                     2.2.1
certifi                     2022.12.7
cffi                        1.15.1
charset-normalizer          3.0.1
click                       8.1.3
colorama                    0.4.6
cryptography                39.0.1
decorator                   5.1.1
fqdn                        1.5.1
fs                          2.4.16
greenlet                    2.0.2
idna                        3.4
inflection                  0.5.1
isoduration                 20.11.0
joblib                      1.2.0
jsonpath-ng                 1.5.3
jsonpointer                 2.3
jsonschema                  4.17.3
meltanolabs-target-postgres 0.0.4.post10+1859883
memoization                 0.4.0
pendulum                    2.1.2
pip                         23.0.1
ply                         3.11
psycopg2-binary             2.9.5
pycparser                   2.21
PyJWT                       2.6.0
pyrsistent                  0.19.3
python-dateutil             2.8.2
python-dotenv               0.21.1
pytz                        2022.7.1
pytzdata                    2020.1
PyYAML                      6.0
requests                    2.28.2
rfc3339-validator           0.1.4
rfc3987                     1.3.8
setuptools                  57.5.0
simplejson                  3.18.3
singer-sdk                  0.19.0
six                         1.16.0
SQLAlchemy                  1.4.46
typing_extensions           4.5.0
uri-template                1.2.0
urllib3                     1.26.14
webcolors                   1.12
wheel                       0.38.4

Original 

(venv) PS C:\development\projects\dev-sql-dataype> meltano run tap-mssql target-postgres
2023-02-25T00:11:07.512888Z [info     ] Environment 'dev' is active
2023-02-25T00:11:10.965926Z [info     ] 2023-02-24 16:11:10,965 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-Error_Log'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:11:10.981551Z [info     ] 2023-02-24 16:11:10,965 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-MoneyTrouble'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:11:10.981551Z [info     ] 2023-02-24 16:11:10,965 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-SmallMoneyTrouble'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:11:10.981551Z [info     ] 2023-02-24 16:11:10,965 | INFO     | tap-mssql            | Beginning full_table sync of 'dbo-TestTable'... cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:11:10.997175Z [info     ] 2023-02-24 16:11:10,965 | INFO     | tap-mssql            | Tap has custom mapper. Using 1 provided map(s). cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:11:11.059678Z [info     ] 2023-02-24 16:11:11,044 | INFO     | singer_sdk.metrics   | INFO METRIC: {"metric_type": "timer", "metric": "sync_duration", "value": 0.0781242847442627, "tags": {"stream": "dbo-TestTable", "context": {}, "status": "succeeded"}} cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:11:11.106553Z [info     ] 2023-02-24 16:11:11,044 | INFO     | singer_sdk.metrics   | INFO METRIC: {"metric_type": "counter", "metric": "record_count", "value": 1, "tags": {"stream": "dbo-TestTable", "context": {}}} cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:11:11.106553Z [info     ] 2023-02-24 16:11:11,044 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-badges'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:11:11.122175Z [info     ] 2023-02-24 16:11:11,044 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-comments'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:11:11.122175Z [info     ] 2023-02-24 16:11:11,044 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-postlinks'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:11:11.122175Z [info     ] 2023-02-24 16:11:11,044 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-posts'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:11:11.137800Z [info     ] 2023-02-24 16:11:11,044 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-tags'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:11:11.184676Z [info     ] 2023-02-24 16:11:11,044 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-users'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:11:11.184676Z [info     ] 2023-02-24 16:11:11,044 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-votes'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:11:11.403417Z [info     ] 2023-02-24 16:11:11,403 | INFO     | target-postgres      | Target 'target-postgres' is listening for input from tap. cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.419039Z [info     ] 2023-02-24 16:11:11,403 | INFO     | target-postgres      | Initializing 'target-postgres' target sink... cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.419039Z [info     ] 2023-02-24 16:11:11,403 | INFO     | target-postgres      | Initializing target sink for stream 'dbo-TestTable'... cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.593046Z [info     ] 2023-02-24 16:11:11,593 | ERROR    | target-postgres      | Exception is being thrown for stream_name: dbo-TestTable cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.593046Z [info     ] Traceback (most recent call last): cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.608658Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\jsonschema\_format.py", line 135, in check cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.608658Z [info     ]     result = func(instance)    cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.608658Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\jsonschema\_format.py", line 407, in is_draft3_time cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.608658Z [info     ]     return bool(datetime.datetime.strptime(instance, "%H:%M:%S")) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres     
2023-02-25T00:11:11.608658Z [info     ]   File "C:\Program Files\Python39\lib\_strptime.py", line 568, in _strptime_datetime cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.608658Z [info     ]     tt, fraction, gmtoff_fraction = _strptime(data_string, format) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres    
2023-02-25T00:11:11.624283Z [info     ]   File "C:\Program Files\Python39\lib\_strptime.py", line 352, in _strptime cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.624283Z [info     ]     raise ValueError("unconverted data remains: %s" % cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.624283Z [info     ] ValueError: unconverted data remains: .001000 cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.624283Z [info     ]                                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.624283Z [info     ] The above exception was the direct cause of the following exception: cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres  
2023-02-25T00:11:11.624283Z [info     ]                                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.639908Z [info     ] Traceback (most recent call last): cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.639908Z [info     ]   File "C:\Program Files\Python39\lib\runpy.py", line 197, in _run_module_as_main cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.639908Z [info     ]     return _run_code(code, main_globals, None, cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.639908Z [info     ]   File "C:\Program Files\Python39\lib\runpy.py", line 87, in _run_code cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres2023-02-25T00:11:11.639908Z [info     ]     exec(code, run_globals)    cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.639908Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\Scripts\target-postgres.exe\__main__.py", line 7, in <module> cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.655531Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\click\core.py", line 1130, in __call__ cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.655531Z [info     ]     return self.main(*args, **kwargs) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.655531Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\click\core.py", line 1055, in main cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.671154Z [info     ]     rv = self.invoke(ctx)      cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.671154Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\click\core.py", line 1404, in invoke cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.671154Z [info     ]     return ctx.invoke(self.callback, **ctx.params) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.671154Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\click\core.py", line 760, in invoke cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.671154Z [info     ]     return __callback(*args, **kwargs) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.686779Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\singer_sdk\target_base.py", line 572, in cli cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.686779Z [info     ]     target.listen(file_input)  cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.686779Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\singer_sdk\io_base.py", line 34, in listen cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.686779Z [info     ]     self._process_lines(file_input) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.702406Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\singer_sdk\target_base.py", line 272, in _process_lines cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.702406Z [info     ]     counter = super()._process_lines(file_input) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.702406Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\singer_sdk\io_base.py", line 81, in _process_lines cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.702406Z [info     ]     self._process_record_message(line_dict) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.702406Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\target_postgres\target.py", line 171, in _process_record_message cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.718029Z [info     ]     raise e                    cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.718029Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\target_postgres\target.py", line 166, in _process_record_message cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.718029Z [info     ]     super()._process_record_message(message_dict) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.718029Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\singer_sdk\target_base.py", line 315, in _process_record_message cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.733651Z [info     ]     sink._validate_and_parse(transformed_record) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.733651Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\singer_sdk\sinks\core.py", line 302, in _validate_and_parse cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.733651Z [info     ]     self._validator.validate(record) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.733651Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\jsonschema\validators.py", line 314, in validate cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.733651Z [info     ]     raise error                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.749280Z [info     ] jsonschema.exceptions.ValidationError: '20:20:39.001000' is not a 'time' cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.749280Z [info     ]                                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.749280Z [info     ] Failed validating 'format' in schema['properties']['TestColumn1']: cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres    
2023-02-25T00:11:11.749280Z [info     ]     {'format': 'time', 'type': ['string', 'null']} cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.749280Z [info     ]                                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.764903Z [info     ] On instance['TestColumn1']:    cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.764903Z [info     ]     '20:20:39.001000'          cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:11:11.780528Z [error    ] Loader failed
2023-02-25T00:11:11.780528Z [error    ] Block run completed.           block_type=ExtractLoadBlocks err=RunnerError('Loader failed') exit_codes={<PluginType.LOADERS: 'loaders'>: 1} set_number=0 success=False     
Need help fixing this problem? Visit http://melta.no/ for troubleshooting steps, or to
join our friendly Slack community.

Run invocation could not be completed as block failed: Loader failed

+00:00 Version 

(venv) PS C:\development\projects\dev-sql-dataype> meltano run tap-mssql target-postgres
2023-02-25T00:12:57.005116Z [info     ] Environment 'dev' is active
2023-02-25T00:13:00.257765Z [info     ] 2023-02-24 16:13:00,257 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-Error_Log'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:00.289014Z [info     ] 2023-02-24 16:13:00,257 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-MoneyTrouble'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:00.289014Z [info     ] 2023-02-24 16:13:00,257 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-SmallMoneyTrouble'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:00.304641Z [info     ] 2023-02-24 16:13:00,257 | INFO     | tap-mssql            | Beginning full_table sync of 'dbo-TestTable'... cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:00.304641Z [info     ] 2023-02-24 16:13:00,257 | INFO     | tap-mssql            | Tap has custom mapper. Using 1 provided map(s). cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:00.351517Z [info     ] 2023-02-24 16:13:00,335 | INFO     | singer_sdk.metrics   | INFO METRIC: {"metric_type": "timer", "metric": "sync_duration", "value": 0.07812714576721191, "tags": {"stream": "dbo-TestTable", "context": {}, "status": "succeeded"}} cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:00.382766Z [info     ] 2023-02-24 16:13:00,335 | INFO     | singer_sdk.metrics   | INFO METRIC: {"metric_type": "counter", "metric": "record_count", "value": 1, "tags": {"stream": "dbo-TestTable", "context": {}}} cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:00.398391Z [info     ] 2023-02-24 16:13:00,335 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-badges'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:00.398391Z [info     ] 2023-02-24 16:13:00,335 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-comments'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:00.398391Z [info     ] 2023-02-24 16:13:00,335 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-postlinks'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:00.398391Z [info     ] 2023-02-24 16:13:00,335 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-posts'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:00.414014Z [info     ] 2023-02-24 16:13:00,335 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-tags'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:00.429638Z [info     ] 2023-02-24 16:13:00,335 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-users'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:00.429638Z [info     ] 2023-02-24 16:13:00,335 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-votes'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:00.492134Z [info     ] 2023-02-24 16:13:00,492 | INFO     | target-postgres      | Target 'target-postgres' is listening for input from tap. cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.507760Z [info     ] 2023-02-24 16:13:00,492 | INFO     | target-postgres      | Initializing 'target-postgres' target sink... cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.507760Z [info     ] 2023-02-24 16:13:00,492 | INFO     | target-postgres      | Initializing target sink for stream 'dbo-TestTable'... cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.679632Z [info     ] 2023-02-24 16:13:00,664 | ERROR    | target-postgres      | Exception is being thrown for stream_name: dbo-TestTable cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.695260Z [info     ] Traceback (most recent call last): cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.695260Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\jsonschema\_format.py", line 135, in check cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.695260Z [info     ]     result = func(instance)    cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.695260Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\jsonschema\_format.py", line 407, in is_draft3_time cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.710884Z [info     ]     return bool(datetime.datetime.strptime(instance, "%H:%M:%S")) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres     
2023-02-25T00:13:00.710884Z [info     ]   File "C:\Program Files\Python39\lib\_strptime.py", line 568, in _strptime_datetime cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.710884Z [info     ]     tt, fraction, gmtoff_fraction = _strptime(data_string, format) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres    
2023-02-25T00:13:00.710884Z [info     ]   File "C:\Program Files\Python39\lib\_strptime.py", line 352, in _strptime cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.710884Z [info     ]     raise ValueError("unconverted data remains: %s" % cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.710884Z [info     ] ValueError: unconverted data remains: .001000+00:00 cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.726509Z [info     ]                                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.726509Z [info     ] The above exception was the direct cause of the following exception: cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres  
2023-02-25T00:13:00.726509Z [info     ]                                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.726509Z [info     ] Traceback (most recent call last): cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.726509Z [info     ]   File "C:\Program Files\Python39\lib\runpy.py", line 197, in _run_module_as_main cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.726509Z [info     ]     return _run_code(code, main_globals, None, cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.742136Z [info     ]   File "C:\Program Files\Python39\lib\runpy.py", line 87, in _run_code cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres2023-02-25T00:13:00.742136Z [info     ]     exec(code, run_globals)    cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.742136Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\Scripts\target-postgres.exe\__main__.py", line 7, in <module> cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.742136Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\click\core.py", line 1130, in __call__ cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.742136Z [info     ]     return self.main(*args, **kwargs) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.742136Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\click\core.py", line 1055, in main cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.757757Z [info     ]     rv = self.invoke(ctx)      cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.757757Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\click\core.py", line 1404, in invoke cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.757757Z [info     ]     return ctx.invoke(self.callback, **ctx.params) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.757757Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\click\core.py", line 760, in invoke cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.757757Z [info     ]     return __callback(*args, **kwargs) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.773380Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\singer_sdk\target_base.py", line 572, in cli cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.773380Z [info     ]     target.listen(file_input)  cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.773380Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\singer_sdk\io_base.py", line 34, in listen cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.773380Z [info     ]     self._process_lines(file_input) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.773380Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\singer_sdk\target_base.py", line 272, in _process_lines cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.773380Z [info     ]     counter = super()._process_lines(file_input) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.789004Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\singer_sdk\io_base.py", line 81, in _process_lines cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.789004Z [info     ]     self._process_record_message(line_dict) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.789004Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\target_postgres\target.py", line 171, in _process_record_message cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.789004Z [info     ]     raise e                    cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.789004Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\target_postgres\target.py", line 166, in _process_record_message cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.804630Z [info     ]     super()._process_record_message(message_dict) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.804630Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\singer_sdk\target_base.py", line 315, in _process_record_message cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.804630Z [info     ]     sink._validate_and_parse(transformed_record) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.804630Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\singer_sdk\sinks\core.py", line 302, in _validate_and_parse cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.820252Z [info     ]     self._validator.validate(record) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.820252Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\jsonschema\validators.py", line 314, in validate cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.820252Z [info     ]     raise error                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.820252Z [info     ] jsonschema.exceptions.ValidationError: '20:20:39.001000+00:00' is not a 'time' cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.820252Z [info     ]                                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.835880Z [info     ] Failed validating 'format' in schema['properties']['TestColumn1']: cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.835880Z [info     ]     {'format': 'time', 'type': ['string', 'null']} cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.835880Z [info     ]                                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.835880Z [info     ] On instance['TestColumn1']:    cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.835880Z [info     ]     '20:20:39.001000+00:00'    cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:00.867128Z [error    ] Loader failed
2023-02-25T00:13:00.867128Z [error    ] Block run completed.           block_type=ExtractLoadBlocks err=RunnerError('Loader failed') exit_codes={<PluginType.LOADERS: 'loaders'>: 1} set_number=0 success=False     
Need help fixing this problem? Visit http://melta.no/ for troubleshooting steps, or to
join our friendly Slack community.

Run invocation could not be completed as block failed: Loader failed

Z Version 

Run invocation could not be completed as block failed: Loader failed
(venv) PS C:\development\projects\dev-sql-dataype> meltano run tap-mssql target-postgres
2023-02-25T00:13:18.995966Z [info     ] Environment 'dev' is active
2023-02-25T00:13:22.308394Z [info     ] 2023-02-24 16:13:22,308 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-Error_Log'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:22.339643Z [info     ] 2023-02-24 16:13:22,308 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-MoneyTrouble'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:22.339643Z [info     ] 2023-02-24 16:13:22,308 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-SmallMoneyTrouble'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:22.355270Z [info     ] 2023-02-24 16:13:22,308 | INFO     | tap-mssql            | Beginning full_table sync of 'dbo-TestTable'... cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:22.355270Z [info     ] 2023-02-24 16:13:22,308 | INFO     | tap-mssql            | Tap has custom mapper. Using 1 provided map(s). cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:22.402145Z [info     ] 2023-02-24 16:13:22,386 | INFO     | singer_sdk.metrics   | INFO METRIC: {"metric_type": "timer", "metric": "sync_duration", "value": 0.0781259536743164, "tags": {"stream": "dbo-TestTable", "context": {}, "status": "succeeded"}} cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:22.449019Z [info     ] 2023-02-24 16:13:22,386 | INFO     | singer_sdk.metrics   | INFO METRIC: {"metric_type": "counter", "metric": "record_count", "value": 1, "tags": {"stream": "dbo-TestTable", "context": {}}} cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:22.449019Z [info     ] 2023-02-24 16:13:22,386 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-badges'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:22.449019Z [info     ] 2023-02-24 16:13:22,386 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-comments'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:22.464643Z [info     ] 2023-02-24 16:13:22,386 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-postlinks'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:22.464643Z [info     ] 2023-02-24 16:13:22,386 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-posts'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:22.464643Z [info     ] 2023-02-24 16:13:22,386 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-tags'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:22.480267Z [info     ] 2023-02-24 16:13:22,386 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-users'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:22.480267Z [info     ] 2023-02-24 16:13:22,386 | INFO     | tap-mssql            | Skipping deselected stream 'dbo-votes'. cmd_type=elb consumer=False name=tap-mssql producer=True stdio=stderr string_id=tap-mssql
2023-02-25T00:13:22.542764Z [info     ] 2023-02-24 16:13:22,542 | INFO     | target-postgres      | Target 'target-postgres' is listening for input from tap. cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.542764Z [info     ] 2023-02-24 16:13:22,542 | INFO     | target-postgres      | Initializing 'target-postgres' target sink... cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.558388Z [info     ] 2023-02-24 16:13:22,542 | INFO     | target-postgres      | Initializing target sink for stream 'dbo-TestTable'... cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.714632Z [info     ] 2023-02-24 16:13:22,714 | ERROR    | target-postgres      | Exception is being thrown for stream_name: dbo-TestTable cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.714632Z [info     ] Traceback (most recent call last): cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.714632Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\jsonschema\_format.py", line 135, in check cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.730261Z [info     ]     result = func(instance)    cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.730261Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\jsonschema\_format.py", line 407, in is_draft3_time cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.730261Z [info     ]     return bool(datetime.datetime.strptime(instance, "%H:%M:%S")) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres     
2023-02-25T00:13:22.730261Z [info     ]   File "C:\Program Files\Python39\lib\_strptime.py", line 568, in _strptime_datetime cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.730261Z [info     ]     tt, fraction, gmtoff_fraction = _strptime(data_string, format) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres    
2023-02-25T00:13:22.730261Z [info     ]   File "C:\Program Files\Python39\lib\_strptime.py", line 352, in _strptime cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.745887Z [info     ]     raise ValueError("unconverted data remains: %s" % cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.745887Z [info     ] ValueError: unconverted data remains: .001000Z cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.745887Z [info     ]                                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.745887Z [info     ] The above exception was the direct cause of the following exception: cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres  
2023-02-25T00:13:22.745887Z [info     ]                                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.745887Z [info     ] Traceback (most recent call last): cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.745887Z [info     ]   File "C:\Program Files\Python39\lib\runpy.py", line 197, in _run_module_as_main cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.761513Z [info     ]     return _run_code(code, main_globals, None, cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.761513Z [info     ]   File "C:\Program Files\Python39\lib\runpy.py", line 87, in _run_code cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres2023-02-25T00:13:22.761513Z [info     ]     exec(code, run_globals)    cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.761513Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\Scripts\target-postgres.exe\__main__.py", line 7, in <module> cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.761513Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\click\core.py", line 1130, in __call__ cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.777139Z [info     ]     return self.main(*args, **kwargs) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.777139Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\click\core.py", line 1055, in main cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.777139Z [info     ]     rv = self.invoke(ctx)      cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.777139Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\click\core.py", line 1404, in invoke cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.777139Z [info     ]     return ctx.invoke(self.callback, **ctx.params) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.777139Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\click\core.py", line 760, in invoke cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.792760Z [info     ]     return __callback(*args, **kwargs) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.792760Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\singer_sdk\target_base.py", line 572, in cli cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.792760Z [info     ]     target.listen(file_input)  cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.792760Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\singer_sdk\io_base.py", line 34, in listen cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.792760Z [info     ]     self._process_lines(file_input) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.792760Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\singer_sdk\target_base.py", line 272, in _process_lines cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.808385Z [info     ]     counter = super()._process_lines(file_input) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.808385Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\singer_sdk\io_base.py", line 81, in _process_lines cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.808385Z [info     ]     self._process_record_message(line_dict) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.808385Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\target_postgres\target.py", line 171, in _process_record_message cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.808385Z [info     ]     raise e                    cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.808385Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\target_postgres\target.py", line 166, in _process_record_message cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.824008Z [info     ]     super()._process_record_message(message_dict) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.824008Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\singer_sdk\target_base.py", line 315, in _process_record_message cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.824008Z [info     ]     sink._validate_and_parse(transformed_record) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.824008Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\singer_sdk\sinks\core.py", line 302, in _validate_and_parse cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.824008Z [info     ]     self._validator.validate(record) cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.824008Z [info     ]   File "C:\development\projects\dev-sql-dataype\.meltano\loaders\target-postgres\venv\lib\site-packages\jsonschema\validators.py", line 314, in validate cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.839631Z [info     ]     raise error                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.839631Z [info     ] jsonschema.exceptions.ValidationError: '20:20:39.001000Z' is not a 'time' cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.839631Z [info     ]                                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.839631Z [info     ] Failed validating 'format' in schema['properties']['TestColumn1']: cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres    
2023-02-25T00:13:22.839631Z [info     ]     {'format': 'time', 'type': ['string', 'null']} cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.839631Z [info     ]                                cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.855259Z [info     ] On instance['TestColumn1']:    cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.855259Z [info     ]     '20:20:39.001000Z'         cmd_type=elb consumer=True name=target-postgres producer=False stdio=stderr string_id=target-postgres
2023-02-25T00:13:22.886505Z [error    ] Loader failed
2023-02-25T00:13:22.902131Z [error    ] Block run completed.           block_type=ExtractLoadBlocks err=RunnerError('Loader failed') exit_codes={<PluginType.LOADERS: 'loaders'>: 1} set_number=0 success=False     
Need help fixing this problem? Visit http://melta.no/ for troubleshooting steps, or to
join our friendly Slack community.

Run invocation could not be completed as block failed: Loader failed

@edgarrmondragon
Copy link
Collaborator

@BuzzCutNorman thanks for the detailed tracebacks. I think I know what's going on.

We need to do change the validator instance:

- Draft7Validator(schema, format_checker=FormatChecker())
+ Draft7Validator(schema, format_checker=Draft7Validator.FORMAT_CHECKER)

for jsonschema to use the right format checker.

Problem is, that then fails for 20:20:39.001000 and 20:20:39 😬.

I think we instead need to use a custom formatter or even let developers override the formatters for time, date-time, date, etc. since different dbs could have different expectations for literals.

@BuzzCutNorman
Copy link
Contributor Author

BuzzCutNorman commented Feb 27, 2023 •
edited
Loading

@edgarrmondragon that is a bit of a pickle. I am a little confused on what is a tap responsible for and what is a target responsible for when it comes to conforming records message data fields. Is it all SDK taps should give properly formatted JSON Schema data and all SDK targets are responsible for conforming JSON schema format to an acceptable target format if necessary?

tap pull -> tap conform -> tap pass to target -> target ingest -> target validate -> target conform -> target load

EDIT:
Working though this using my example here are the steps I have in my head. In the tap I need to overload _conform_primitive_property or another method that does the same thing so I can transform MS SQL time fields from this 20:20:39.001000 into an ISO format 20:20:39.001000+00:00 or 20:20:39.001000Z. Then on the target side the value of 20:20:39.001000+00:00 is valid, so the records are given to SQL Server which fails to insert them. Like you said:

I think we instead need to use a custom formatter or even let developers override the formatters for time, date-time, date, etc. since different dbs could have different expectations for literals.

I would adjust the custom formatter to allow hh:mm:ss.nnnnnn then validation would fail so a conform step would be triggered. A target version of _conform_primitive_property, maybe conform_records could be expanded, would fix this to 20:20:39.001000 and revalidate before attempting to insert them.

Does this match up with what you were suggesting above?

@BuzzCutNorman
Copy link
Contributor Author

BuzzCutNorman commented Mar 1, 2023 •
edited
Loading

@edgarrmondragon I added an import for the jsonschema validator(s) and also added an __init__ to buzzcutnorman-target-mssql's mssqlSink class to change the self._validator value. Everything seems to be working 👍.

from jsonschema import  Draft202012Validator
...
class mssqlSink(SQLSink):
    """mssql target sink class."""

...

    def __init__(
            self, 
            target: PluginBase, 
            stream_name: str, 
            schema: Dict, 
            key_properties: list[str] | None, 
            connector: Optional[SQLConnector] = None
    ) -> None:
        super().__init__(target, stream_name, schema, key_properties, connector)
        # Setup the JSONSchema validator and format_checker combonation you want
        # The defualt is version 3 unless you chagne this
        self._validator = Draft202012Validator(schema, format_checker=Draft202012Validator.FORMAT_CHECKER)

I have checked all four time formats :

  • 20:20:39.00100
  • 20:20:39
  • 20:20:39.00100+00:00
  • 20:20:39.00100Z

by running them through the following validator, validator format checker combos.

  • Draft7Validator, Draft7Validator.FROMAT_CHECHER
  • Draft201909Validator, Draft201909Validator.FORMAT_CHECKER
  • Draft202012Validator, Draft202012Validator.FROMAT_CHECKER

All four time formats passed validation for each combo listed above 😮‍💨🎉.

Thank you 🙏 for taking time to track down the source of this issue.

I think we instead need to use a custom formatter or even let developers override the formatters for time, date-time, date, etc. since different dbs could have different expectations for literals.

I agree an easier way for developers to override would be a nice touch.

@edgarrmondragon
Copy link
Collaborator

edgarrmondragon commented Mar 1, 2023 •
edited
Loading

@BuzzCutNorman Thanks for sharing your findings! This is great insight so I started a draft PR to support both custom validators and format checkers:

@BuzzCutNorman
Copy link
Contributor Author

@edgarrmondragon I tested the draft PR out with buzzcutnorman-target-mssql and buzzcutnorman-target-postgres. Everything worked great and the time jsonschema format validation error was resolved by using the draft PR version of the SDK.

@edgarrmondragon
Copy link
Collaborator

  • Draft7Validator, Draft7Validator.FROMAT_CHECHER
  • Draft201909Validator, Draft201909Validator.FORMAT_CHECKER
  • Draft202012Validator, Draft202012Validator.FROMAT_CHECKER

These examples give me pause. It makes sense that devs would like pairing validators and checkers like that, and my current implementation forces them to override both methods. I'll give it some thought over the weekend.

@edgarrmondragon edgarrmondragon self-assigned this Mar 30, 2023
@BuzzCutNorman BuzzCutNorman mentioned this issue Jan 11, 2024
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@edgarrmondragon edgarrmondragon

Labels
kind/Bug Something isn't working valuestream/SDK
Projects
None yet
Milestone
No milestone
2 participants
@edgarrmondragon @BuzzCutNorman