create_vm fails with postgres SQL error with CPI v72

[JCL38-ORANGE]

Describe the bug
create_vm fails with postgres SQL error with CPI v72

To Reproduce
cloud_config extract :

networks:
- name: tf-net-osb-data-plane-dedicated-priv
  subnets:
    azs:
    - z1
    - z2
    - z3
    cloud_properties:
      name: vxw-dvs-27-virtualwire-99-sid-7050-VXS_in_tf-net-osb-data-plane-dedicated-priv
    gateway: 192.168.61.1
    range: 192.168.61.0/24
    reserved:
    - 192.168.61.1 - 192.168.61.20

CPI Error Log

D, [2021-12-02T15:03:31.712189 #11308] [task:5894640] DEBUG -- DirectorJobRunner: (0.000524s) (conn: 47264853264400) UPDATE "tasks" SET "event_output" = ("event_output" || '{"time":1638457411,"error":{"code":100,"message":"PG::InvalidTextRepresentation: ERROR:  invalid input syntax for type boolean: \"cloud_properties\"\nLINE 1: ...68.61.34'') AND (''netmask'' = ''255.255.255.0'') AND (''cloud_pro...\n                                                             ^\n"}}
') WHERE ("id" = 5894640)
D, [2021-12-02T15:03:31.752886 #11308] [task:5894640] DEBUG -- DirectorJobRunner: (0.040494s) (conn: 47264853264400) COMMIT
E, [2021-12-02T15:03:31.753338 #11308] [task:5894640] ERROR -- DirectorJobRunner: PG::InvalidTextRepresentation: ERROR:  invalid input syntax for type boolean: "cloud_properties"
LINE 1: ...68.61.34') AND ('netmask' = '255.255.255.0') AND ('cloud_pro...
                                                             ^

/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/adapters/postgres.rb:152:in `exec'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/adapters/postgres.rb:152:in `block in execute_query'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/database/logging.rb:43:in `log_connection_yield'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/adapters/postgres.rb:152:in `execute_query'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/adapters/postgres.rb:140:in `block in execute'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/adapters/postgres.rb:116:in `check_disconnect_errors'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/adapters/postgres.rb:140:in `execute'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/adapters/postgres.rb:496:in `_execute'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/adapters/postgres.rb:314:in `block (2 levels) in execute'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/adapters/postgres.rb:518:in `check_database_errors'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/adapters/postgres.rb:314:in `block in execute'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/connection_pool/threaded.rb:88:in `hold'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/database/connecting.rb:270:in `synchronize'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/adapters/postgres.rb:314:in `execute'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/dataset/actions.rb:1083:in `execute'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/adapters/postgres.rb:610:in `fetch_rows'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/dataset/actions.rb:937:in `with_sql_each'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/dataset/actions.rb:945:in `with_sql_first'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/adapters/shared/postgres.rb:1553:in `insert_select'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/model/base.rb:1709:in `_insert_select_raw'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/model/base.rb:1682:in `_insert'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/model/base.rb:1753:in `block (2 levels) in _save'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/model/base.rb:1015:in `around_create'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/model/base.rb:1750:in `block in _save'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/model/base.rb:1015:in `around_save'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/model/base.rb:1745:in `_save'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/model/base.rb:1465:in `block (2 levels) in save'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/model/base.rb:1905:in `block in checked_transaction'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/database/transactions.rb:245:in `_transaction'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/database/transactions.rb:220:in `block in transaction'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/connection_pool/threaded.rb:92:in `hold'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/database/connecting.rb:270:in `synchronize'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/database/transactions.rb:186:in `transaction'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/model/base.rb:1905:in `checked_transaction'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/model/base.rb:1465:in `block in save'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/model/base.rb:1893:in `checked_save_failure'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/model/base.rb:1465:in `save'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/sequel-5.16.0/lib/sequel/model/base.rb:254:in `create'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/bosh-director-0.0.0/lib/bosh/director/api/event_manager.rb:42:in `create_event'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/bosh-director-0.0.0/lib/bosh/director/deployment_plan/steps/create_vm_step.rb:166:in `add_event'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/bosh-director-0.0.0/lib/bosh/director/deployment_plan/steps/create_vm_step.rb:162:in `ensure in create'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/bosh-director-0.0.0/lib/bosh/director/deployment_plan/steps/create_vm_step.rb:162:in `create'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/bosh-director-0.0.0/lib/bosh/director/deployment_plan/steps/create_vm_step.rb:27:in `perform'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/bosh-director-0.0.0/lib/bosh/director/step_executor.rb:39:in `block in run_agenda'
                /var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/bosh-director-0.0.0/lib/bosh/director/step_executor.rb:36:in `each'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/bosh-director-0.0.0/lib/bosh/director/step_executor.rb:36:in `run_agenda'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/bosh-director-0.0.0/lib/bosh/director/step_executor.rb:21:in `block (5 levels) in run'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/bosh-director-0.0.0/lib/bosh/director/event_log.rb:105:in `advance_and_track'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/bosh-director-0.0.0/lib/bosh/director/step_executor.rb:20:in `block (4 levels) in run'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/bosh_common-0.0.0/lib/common/thread_formatter.rb:50:in `with_thread_name'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/bosh-director-0.0.0/lib/bosh/director/step_executor.rb:18:in `block (3 levels) in run'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/bosh_common-0.0.0/lib/common/thread_pool.rb:77:in `block (2 levels) in create_thread'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/bosh_common-0.0.0/lib/common/thread_pool.rb:63:in `loop'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/bosh_common-0.0.0/lib/common/thread_pool.rb:63:in `block in create_thread'
/var/vcap/data/packages/director/87427387c8b374a15842eb951bb2cef3b10afb12/gem_home/ruby/2.6.0/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
D, [2021-12-02T15:03:31.755025 #11308] [task:5894640] DEBUG -- DirectorJobRunner: (0.000375s) (conn: 47264853268480) SELECT * FROM "tasks" WHERE "id" = 5894640
D, [2021-12-02T15:03:31.757519 #11308] [task:5894640] DEBUG -- DirectorJobRunner: (0.000131s) (conn: 47264854487260) BEGIN
D, [2021-12-02T15:03:31.758981 #11308] [task:5894640] DEBUG -- DirectorJobRunner: (0.000611s) (conn: 47264854487260) UPDATE "tasks" SET "state" = 'error', "timestamp" = '2021-12-02 15:03:31.756516+0000', "description" = 'create deployment', "result" = 'PG::InvalidTextRepresentation: ERROR:  invalid input syntax for type boolean:
LINE 1: ...68.61.34'') AND...', "output" = '/var/vcap/store/director/tasks/5894640', "checkpoint_time" = '2021-12-02 15:03:14.991645+0000', "type" = 'update_deployment', "username" = 'admin', "deployment_name" = 'y_7186f856-b982-41f9-9e60-c28dae205d1b', "started_at" = '2021-12-02 15:02:44.991574+0000', "event_output" = '{"time":1638457369,"stage":"Preparing deployment","tags":[],"total":1,"task":"Preparing deployment","index":1,"state":"started","progress":0}

Expected behavior
success for create_vm

Release Version & Related Info (please complete the following information):

• CPI : 72
• BOSH Director : 271.8.0
• Stemcell : Bionic 1.34
• vCenter : 6.7

Additional context
Bump CPI from v66 to v72

[rkoster]

Which version of Postgres are you using?

[JCL38-ORANGE]

Hello,

Sorry for my late answer.
postgres-10 is used.
Regards,
Jean-Christophe.

[rkoster]

Could you try upgrading to postgres-13. Which is what is being used by bosh-deployment.

[ragaskar]

Hi @JCL38-ORANGE -- just wanted to check in and see if moving to postgres-13 resolved your problem. thanks!

[JCL38-ORANGE]

Hello,

I am going to test it this week. I keep you informed.
Regards,
Jean-Christophe.

[JCL38-ORANGE]

Hello,

With Postgres-13 is still failing.
Some new informations on that. It seems related to a multi-cpi context with both vsphere and openstack stemcells.
The method create_missing_vm inserts a record in the vms table and more precisely in the column cid.

When the insertion is a success (CPI v66), the cid column contains a String with the "vm-guid" and POSTGRES doesn't complain about that.
For example :

INSERT INTO "vms" ("instance_id", 
"agent_id", 
"cpi", 
"blobstore_config_sha1", 
"nats_config_sha1", 
**"cid"**, 
"created_at", 
"stemcell_api_version") VALUES (
2498, 
'5928fea7-6abf-4056-bc05-12a4a6a7a029', '', 
'75fd2c7097f88c4bcced6a2bba7e1effa670db03', 
'ca9255aa6982364cd639cd1b088ae369a9fa04af', 
**'vm-f9a7281e-7012-4584-9039-e26551dae37f'**, 
'2022-03-28 16:04:46.345920+0000', 3)

When the insertion is a failure (CPI v72), the cid column contains a String with the "vm-guid" and a part of the cloud-config :

INSERT INTO "vms" ("instance_id", 
"agent_id", 
"cpi", 
"blobstore_config_sha1", 
"nats_config_sha1", 
**"cid"**, 
"created_at", 
"stemcell_api_version") VALUES (
8527, 
'7f81992c-15cb-441d-baf4-538bf187798c', 
'region-1', 
'df8391816f2042730b8d498bddf0aac34975420b', 
'8f64c1a90fa99e8d674d3b235b3ceee3ff0eb0ac', 
**('vm-854ceb4a-b970-47f4-804c-6ce8ecfc0db4', ('tf-net-osb-data-plane-dedicated-priv' = (('type' = 'manual') AND ('ip' = '192.168.61.59') AND ('netmask' = '255.255.255.0') AND ('cloud_properties' = ('name' = 'vxw-dvs-27-virtualwire-99-sid-7050-VXS_in_tf-net-osb-data-plane-dedicated-priv')) AND ('default' IN ('dns', 'gateway')) AND ('gateway' = '192.168.61.1'))))**, 
'2022-03-28 13:17:44.983321+0000', 
3) 

In this case POSTGRES complains about that...

Thanks for your help,
Regards,
Jean-Christophe.

[JCL38-ORANGE]

Hello,

In fact, we have on our side a flag which causes the error.

- type: replace
  path: /instance_groups/name=bosh/properties/director/cpi?
  value:
    preferred_api_version: 1

It is now ok with the flag removal.

Thanks and regards,
Jean-Christophe.

[bosh-admin-bot]

This issue was marked as Stale because it has been open for 21 days without any activity. If no activity takes place in the coming 7 days it will automatically be close. To prevent this from happening remove the Stale label or comment below.

[rkoster]

This issue seems to be resolved, closing.