Underlying errors are suppressed

[rvangraan]

Hi there,

I'm trying to troubleshoot an issue in one of our scripts. For some reason, SEM does not print the details of the underlying Postgres problem when applying the change, like you can see in this log:

Upgrading schema for postgres://schemaManagerRole@schema-system-test.ckanakw8vqgo.eu-west-1.rds.amazonaws.com:5432/afoom
Applying 20160424-112521.sql

ERROR applying script: 20160424-112521.sql

If this script has previously been applied to this database, you can record it as having been applied by:
 psql --command "insert into schema_evolution_manager.scripts (filename) values ('20160424-112521.sql')" postgres://schemaManagerRole@schema-system-test.ckanakw8vqgo.eu-west-1.rds.amazonaws.com:5432/afoom

Is there anything you can suggest that will help me get the details out so we can figure out what is wrong?

[mbryzek]

One option is to run the script yourself:

psql --file scripts/20160424-112521.sql postgres://schemaManagerRole@schema-system-test.ckanakw8vqgo.eu-west-1.rds.amazonaws.com:5432/afoom

and you will get the error directly

[rvangraan]

We've done this. There isn't any obvious problem with the script. This error only happens when we do automated deployments in AWS, and the error is somehow related to how the environment behaves. We don't see any errors when we run it ourselves. This is why I'm desperate to see the output that is not visible now.

[mbryzek]

Got it.

Is this blocking you (i.e. is this an emergency) or have you manually deployed this file to keep things moving?

I will take a look and see if there is a way to get the test output echoed (though I think I'll be guessing a little a bit as to what is going on w/out access to environment so might take a few tries)

[rvangraan]

It is blocking us, but I've now started to setup a duplicate environment and I'll soon be able to run the scripts by hand. I will probably be able to find the issue, but it would be nice if you can help getting the real error messages to display for future purposes :)

[mbryzek]

ack - I'm working on a fix - hope to have something for you to try by end of day EST

[rvangraan]

Nope - the error doesn't happen when I manually run the script.

[mbryzek]

Have published a new version - 0.9.28 - based on this PR:

#40

Hopefully this is a more reliable way of capturing and output send to STDOUT / STDERR.

Would you be able to install this version and let me know if it improves the information back?

[rvangraan]

Wow thanks! I've had a go and the problem is... unicode!

sem/lib/schema-evolution-manager-0.9.28/lib/schema-evolution-manager/migration_file.rb:83:in `match': invalid byte sequence in US-ASCII (ArgumentError)
    from sem/lib/schema-evolution-manager-0.9.28/lib/schema-evolution-manager/migration_file.rb:83:in `match'
    from sem/lib/schema-evolution-manager-0.9.28/lib/schema-evolution-manager/migration_file.rb:83:in `block in each_property'
    from sem/lib/schema-evolution-manager-0.9.28/lib/schema-evolution-manager/migration_file.rb:81:in `each'
    from sem/lib/schema-evolution-manager-0.9.28/lib/schema-evolution-manager/migration_file.rb:81:in `each_property'
    from sem/lib/schema-evolution-manager-0.9.28/lib/schema-evolution-manager/migration_file.rb:62:in `parse_attribute_values'
    from sem/lib/schema-evolution-manager-0.9.28/lib/schema-evolution-manager/migration_file.rb:52:in `initialize'
    from sem/lib/schema-evolution-manager-0.9.28/lib/schema-evolution-manager/db.rb:44:in `new'
    from sem/lib/schema-evolution-manager-0.9.28/lib/schema-evolution-manager/db.rb:44:in `attribute_values'
    from sem/lib/schema-evolution-manager-0.9.28/lib/schema-evolution-manager/db.rb:66:in `psql_file'
    from sem/lib/schema-evolution-manager-0.9.28/lib/schema-evolution-manager/apply_util.rb:33:in `block in apply!'
    from sem/lib/schema-evolution-manager-0.9.28/lib/schema-evolution-manager/scripts.rb:58:in `block in each_pending'
    from sem/lib/schema-evolution-manager-0.9.28/lib/schema-evolution-manager/scripts.rb:52:in `each'
    from sem/lib/schema-evolution-manager-0.9.28/lib/schema-evolution-manager/scripts.rb:52:in `each_pending'
    from sem/lib/schema-evolution-manager-0.9.28/lib/schema-evolution-manager/apply_util.rb:25:in `apply!'
    from sem/bin/sem-apply:33:in `<main>'

[rvangraan]

Initially I discovered that the issue is the no locale is set in the docker container. I did that, but it seems that SEM does not get the locale correctly. It is now:

root@ebf72b9daa71:/# locale LANG=en_GB.UTF-8 LANGUAGE=en_GB:en LC_CTYPE="en_GB.UTF-8" LC_NUMERIC="en_GB.UTF-8" LC_TIME="en_GB.UTF-8" LC_COLLATE="en_GB.UTF-8" LC_MONETARY="en_GB.UTF-8" LC_MESSAGES="en_GB.UTF-8" LC_PAPER="en_GB.UTF-8" LC_NAME="en_GB.UTF-8" LC_ADDRESS="en_GB.UTF-8" LC_TELEPHONE="en_GB.UTF-8" LC_MEASUREMENT="en_GB.UTF-8" LC_IDENTIFICATION="en_GB.UTF-8" LC_ALL=en_GB.UTF-8

Any suggestions on how the locale is propagated?

[rvangraan]

I managed to get past the problem by removing all unicode chars from the scripts. But that is hacky.

[mbryzek]

I was able to replicate locally and pushed a fix here:

#42

If you don't mind, could you pls try version 0.9.29 to see if the problem is fixed? You will NOT need to change your source file.

[rvangraan]

Hey, I tried it but the error just moved elsewhere:

sem/lib/schema-evolution-manager-0.9.29/lib/schema-evolution-manager/migration_file.rb:81:in `readlines': "\xC3" on US-ASCII (Encoding::InvalidByteSequenceError)
    from sem/lib/schema-evolution-manager-0.9.29/lib/schema-evolution-manager/migration_file.rb:81:in `each_property'
    from sem/lib/schema-evolution-manager-0.9.29/lib/schema-evolution-manager/migration_file.rb:62:in `parse_attribute_values'
    from sem/lib/schema-evolution-manager-0.9.29/lib/schema-evolution-manager/migration_file.rb:52:in `initialize'
    from sem/lib/schema-evolution-manager-0.9.29/lib/schema-evolution-manager/db.rb:44:in `new'
    from sem/lib/schema-evolution-manager-0.9.29/lib/schema-evolution-manager/db.rb:44:in `attribute_values'
    from sem/lib/schema-evolution-manager-0.9.29/lib/schema-evolution-manager/db.rb:66:in `psql_file'
    from sem/lib/schema-evolution-manager-0.9.29/lib/schema-evolution-manager/apply_util.rb:33:in `block in apply!'
    from sem/lib/schema-evolution-manager-0.9.29/lib/schema-evolution-manager/scripts.rb:58:in `block in each_pending'
    from sem/lib/schema-evolution-manager-0.9.29/lib/schema-evolution-manager/scripts.rb:52:in `each'
    from sem/lib/schema-evolution-manager-0.9.29/lib/schema-evolution-manager/scripts.rb:52:in `each_pending'
    from sem/lib/schema-evolution-manager-0.9.29/lib/schema-evolution-manager/apply_util.rb:25:in `apply!'
    from sem/bin/sem-apply:33:in `<main>'

This is the SQL that triggers the error:

INSERT INTO master.currency (currency_code, decimals, numeric_code, name) VALUES ('ISK', 0, 352, 'Icelandic króna');
INSERT INTO master.currency (currency_code, decimals, numeric_code, name) VALUES ('MNT', 2, 496, 'Mongolian tögrög');
INSERT INTO master.currency (currency_code, decimals, numeric_code, name) VALUES ('PLN', 2, 985, 'Polish złoty');
INSERT INTO master.currency (currency_code, decimals, numeric_code, name) VALUES ('STD', 2, 678, 'São Tomé and Príncipe dobra');
INSERT INTO master.currency (currency_code, decimals, numeric_code, name) VALUES ('NIO', 2, 558, 'Nicaraguan Nicaraguan córdoba');
INSERT INTO master.currency (currency_code, decimals, numeric_code, name) VALUES ('TOP', 2, 776, 'Tongan paʻanga');
INSERT INTO master.currency (currency_code, decimals, numeric_code, name) VALUES ('VEF', 2, 937, 'Venezuelan bolívar');
INSERT INTO master.currency (currency_code, decimals, numeric_code, name) VALUES ('PYG', 0, 600, 'Paraguayan guaraní');

[mbryzek]

Thanks - a new version is out:

0.9.31

which hopefully addresses this one - if you can, would appreciate any feedback if this fixes the core issue.

thanks again,
Mike