collins
collins copied to clipboard
Race condition when doing parallelized asset intake / configuration
In a test environment, I have setup several test assets that I "intake" in parallel. This can produce stack traces and errors in provisioning:
Trace 1: Unique index or primary key violation
**CLICK TO EXPAND**
2017-02-01 15:58:52,793 - [WARN] - o.a.s.c.SolrCore - o.a.s.c.SolrCore:getSearcher:1761 - [collins] PERFORMANCE WARNING: Overlapping onDeckSearchers=2
2017-02-01 15:58:54,146 - [WARN] - application - c.m.AssetLifecycle:collins$models$AssetLifecycle$$handleException:303 - Error saving attributes for asset
java.lang.RuntimeException: Exception while executing statement : Unique index or primary key violation: "CONSTRAINT_9D9B1_INDEX_F ON PUBLIC.ASSET_META(NAME) VALUES (CAST('SUFFIX' AS VARCHAR_IGNORECASE), 48)"; SQL statement:
insert into asset_meta (name, priority, value_type, description, label) values (?,?,?,?,?) [23505-188]
errorCode: 23505, sqlState: 23505
insert into asset_meta (name, priority, value_type, description, label) values (?,?,?,?,?)
jdbcParams:[SUFFIX,-1,1,SUFFIX,Suffix]
at org.squeryl.internals.DatabaseAdapter$class._exec(DatabaseAdapter.scala:297) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
at org.squeryl.internals.DatabaseAdapter$class.exec(DatabaseAdapter.scala:349) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
at org.squeryl.adapters.H2Adapter.exec(H2Adapter.scala:22) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
at org.squeryl.internals.DatabaseAdapter$class.executeUpdateForInsert(DatabaseAdapter.scala:383) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
at org.squeryl.adapters.H2Adapter.executeUpdateForInsert(H2Adapter.scala:22) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
Caused by: org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: "CONSTRAINT_9D9B1_INDEX_F ON PUBLIC.ASSET_META(NAME) VALUES (CAST('SUFFIX' AS VARCHAR_IGNORECASE), 48)"; SQL statement:
insert into asset_meta (name, priority, value_type, description, label) values (?,?,?,?,?) [23505-188]
at org.h2.message.DbException.getJdbcSQLException(DbException.java:345) ~[com.h2database.h2-1.4.188.jar:1.4.188]
at org.h2.message.DbException.get(DbException.java:179) ~[com.h2database.h2-1.4.188.jar:1.4.188]
at org.h2.message.DbException.get(DbException.java:155) ~[com.h2database.h2-1.4.188.jar:1.4.188]
at org.h2.index.BaseIndex.getDuplicateKeyException(BaseIndex.java:102) ~[com.h2database.h2-1.4.188.jar:1.4.188]
at org.h2.mvstore.db.MVSecondaryIndex.checkUnique(MVSecondaryIndex.java:231) ~[com.h2database.h2-1.4.188.jar:1.4.188]
2017-02-01 15:58:54,795 - [WARN] - o.a.s.c.SolrCore - o.a.s.c.SolrCore:getSearcher:1761 - [collins] PERFORMANCE WARNING: Overlapping onDeckSearchers=2
Trace2: java.util.NoSuchElementException: None.get
**CLICK TO EXPAND**
2017-02-01 16:17:35,551 - [WARN] - application - c.m.AssetLifecycle:collins$models$AssetLifecycle$$handleException:303 - Error saving attributes for asset
java.util.NoSuchElementException: None.get
at scala.None$.get(Option.scala:347) ~[org.scala-lang.scala-library-2.11.7.jar:na]
at scala.None$.get(Option.scala:345) ~[org.scala-lang.scala-library-2.11.7.jar:na]
at collins.models.AssetMetaValue.meta$lzycompute(AssetMetaValue.scala:32) ~[collins.collins-2.0-SNAPSHOT.jar:2.0-SNAPSHOT]
at collins.models.AssetMetaValue.meta(AssetMetaValue.scala:32) ~[collins.collins-2.0-SNAPSHOT.jar:2.0-SNAPSHOT]
at collins.models.AssetMetaValue.<init>(AssetMetaValue.scala:34) ~[collins.collins-2.0-SNAPSHOT.jar:2.0-SNAPSHOT]
2017-02-01 16:17:35,555 - [WARN] - application - c.m.AssetLifecycle:collins$models$AssetLifecycle$$handleException:303 - Error saving attributes for asset
~Interestingly, it doesn't seem to result in an error to the client but also does not correctly write the data to the database.~ (See first comment)
I am running the docker container with (mostly) standard / default configurations under systemd, and have 7 units (#s 10-16) looking like this:
[Unit]
After=collins.service [email protected]
BindsTo=collins.service
Description=Collins MySQL Node Intake: mysql-container-13
Wants=collins.service
[Service]
ExecStart=/path/to/collins-intake-mysql-container-13-start
Type=oneshot
#! /bin/bash -e
URL="http://localhost:9000/api/asset"
TAG="mysql-container-13"
LLDP_FILE="./single.lldp"
LSHW_FILE="./virident.lshw"
curl --basic -X PUT -H "Accept: text/plain" \
-u blake:admin:first "$URL/$TAG"
curl --basic -H "Accept: text/plain" -u blake:admin:first \
--data-urlencode "lldp@$LLDP_FILE" \
--data-urlencode "lshw@$LSHW_FILE" \
--data-urlencode 'CHASSIS_TAG=Testing this' \
"$URL/$TAG"
collins modify -C "./collins-cli.yaml" -t "mysql-container-13" -S maintenance:maint_noop -r "Provisioning"
collins provision -C "./collins-cli.yaml" -t "mysql-container-13" -n databasenode -r DATABASE -b blake
collins modify -C "./collins-cli.yaml" -t "mysql-container-13" \
-S Allocated:SPARE \
-r "Provisioning" \
-a "HOSTNAME:mysql-container-13"
curl --basic -u blake:admin:first -X POST \
-d pool=DATABASE \
-d address=10.50.2.13 \
-d gateway=10.50.2.1 \
-d netmask=255.255.255.0 \
http://localhost:9000/api/asset/mysql-container-13/address
Unfortunately, since it doesn't seem to fail in the response, I'm not sure what step failed.
I was able to reproduce these issues in about 9 out of 10 test runs, and can share with you instructions on how to reproduce what I'm seeing (using tooling which is not public at this time.)
Ok, so I crossed-out the part about not updating the database.
I've seen this happen at least once:
+ curl --basic -u blake:admin:first -X POST -d pool=DATABASE -d address=10.50.2.10 -d gateway=10.50.2.1 -d netmask=255.255.255.0 http://localhost:9000/api/asset/mysql-container-10/address
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
[158B blob data]
{"status":"error","data":{"message":"Unable to update address: ...
(but didn't catch the http response code...)
but
sometimes it doesn't seem to - CLICK TO EXPAND
This is a big log, but I believe it is showing errors corresponding to SUCCESSes...
Feb 01 17:47:39 nixos collins-intake-mysql-container-16-start[6090]: + collins modify -C /nix/store/diyzwylw4dv42362vysbks5av57pjh0b-collins-cli.yaml -t mysql-container-16 -S maintenance:maint_noop -r Provisioning
Feb 01 17:47:40 nixos collins-intake-mysql-container-15-start[6096]: mysql-container-15 changing status to MAINTENANCE:MAINT_NOOP... SUCCESS
Feb 01 17:47:40 nixos collins-intake-mysql-container-15-start[6096]: + collins provision -C /nix/store/diyzwylw4dv42362vysbks5av57pjh0b-collins-cli.yaml -t mysql-container-15 -n databasenode -r DATABASE -b blake
Feb 01 17:47:40 nixos docker[5807]: 2017-02-01 17:47:40,437 - [WARN] - application - c.m.AssetLifecycle:collins$models$AssetLifecycle$$handleException:303 - Error saving attributes for asset
Feb 01 17:47:40 nixos docker[5807]: java.lang.RuntimeException: Exception while executing statement : Unique index or primary key violation: "CONSTRAINT_9D9B1_INDEX_F ON PUBLIC.ASSET_META(NAME) VALUES (CAST('SUFFIX' AS VARCHAR_IGN
Feb 01 17:47:40 nixos docker[5807]: insert into asset_meta (name, priority, value_type, description, label) values (?,?,?,?,?) [23505-188]
Feb 01 17:47:40 nixos docker[5807]: errorCode: 23505, sqlState: 23505
Feb 01 17:47:40 nixos docker[5807]: insert into asset_meta (name, priority, value_type, description, label) values (?,?,?,?,?)
Feb 01 17:47:40 nixos docker[5807]: jdbcParams:[SUFFIX,-1,1,SUFFIX,Suffix]
Feb 01 17:47:40 nixos docker[5807]: at org.squeryl.internals.DatabaseAdapter$class._exec(DatabaseAdapter.scala:297) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
Feb 01 17:47:40 nixos docker[5807]: at org.squeryl.internals.DatabaseAdapter$class.exec(DatabaseAdapter.scala:349) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
Feb 01 17:47:40 nixos docker[5807]: at org.squeryl.adapters.H2Adapter.exec(H2Adapter.scala:22) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
Feb 01 17:47:40 nixos docker[5807]: at org.squeryl.internals.DatabaseAdapter$class.executeUpdateForInsert(DatabaseAdapter.scala:383) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
Feb 01 17:47:40 nixos docker[5807]: at org.squeryl.adapters.H2Adapter.executeUpdateForInsert(H2Adapter.scala:22) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
Feb 01 17:47:40 nixos docker[5807]: Caused by: org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: "CONSTRAINT_9D9B1_INDEX_F ON PUBLIC.ASSET_META(NAME) VALUES (CAST('SUFFIX' AS VARCHAR_IGNORECASE), 48)"; SQL state
Feb 01 17:47:40 nixos docker[5807]: insert into asset_meta (name, priority, value_type, description, label) values (?,?,?,?,?) [23505-188]
Feb 01 17:47:40 nixos docker[5807]: at org.h2.message.DbException.getJdbcSQLException(DbException.java:345) ~[com.h2database.h2-1.4.188.jar:1.4.188]
Feb 01 17:47:40 nixos docker[5807]: at org.h2.message.DbException.get(DbException.java:179) ~[com.h2database.h2-1.4.188.jar:1.4.188]
Feb 01 17:47:40 nixos docker[5807]: at org.h2.message.DbException.get(DbException.java:155) ~[com.h2database.h2-1.4.188.jar:1.4.188]
Feb 01 17:47:40 nixos docker[5807]: at org.h2.index.BaseIndex.getDuplicateKeyException(BaseIndex.java:102) ~[com.h2database.h2-1.4.188.jar:1.4.188]
Feb 01 17:47:40 nixos dockerd[883]: 2017-02-01 17:47:40,437 - [WARN] - application - c.m.AssetLifecycle:collins$models$AssetLifecycle$$handleException:303 - Error saving attributes for asset
Feb 01 17:47:40 nixos docker[5807]: at org.h2.mvstore.db.MVSecondaryIndex.checkUnique(MVSecondaryIndex.java:231) ~[com.h2database.h2-1.4.188.jar:1.4.188]
Feb 01 17:47:40 nixos dockerd[883]: java.lang.RuntimeException: Exception while executing statement : Unique index or primary key violation: "CONSTRAINT_9D9B1_INDEX_F ON PUBLIC.ASSET_META(NAME) VALUES (CAST('SUFFIX' AS VARCHAR_IGN
Feb 01 17:47:40 nixos dockerd[883]: insert into asset_meta (name, priority, value_type, description, label) values (?,?,?,?,?) [23505-188]
Feb 01 17:47:40 nixos dockerd[883]: errorCode: 23505, sqlState: 23505
Feb 01 17:47:40 nixos dockerd[883]: insert into asset_meta (name, priority, value_type, description, label) values (?,?,?,?,?)
Feb 01 17:47:40 nixos dockerd[883]: jdbcParams:[SUFFIX,-1,1,SUFFIX,Suffix]
Feb 01 17:47:40 nixos dockerd[883]: at org.squeryl.internals.DatabaseAdapter$class._exec(DatabaseAdapter.scala:297) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
Feb 01 17:47:40 nixos dockerd[883]: at org.squeryl.internals.DatabaseAdapter$class.exec(DatabaseAdapter.scala:349) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
Feb 01 17:47:40 nixos dockerd[883]: at org.squeryl.adapters.H2Adapter.exec(H2Adapter.scala:22) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
Feb 01 17:47:40 nixos dockerd[883]: at org.squeryl.internals.DatabaseAdapter$class.executeUpdateForInsert(DatabaseAdapter.scala:383) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
Feb 01 17:47:40 nixos dockerd[883]: at org.squeryl.adapters.H2Adapter.executeUpdateForInsert(H2Adapter.scala:22) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
Feb 01 17:47:40 nixos dockerd[883]: Caused by: org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: "CONSTRAINT_9D9B1_INDEX_F ON PUBLIC.ASSET_META(NAME) VALUES (CAST('SUFFIX' AS VARCHAR_IGNORECASE), 48)"; SQL state
Feb 01 17:47:40 nixos dockerd[883]: insert into asset_meta (name, priority, value_type, description, label) values (?,?,?,?,?) [23505-188]
Feb 01 17:47:40 nixos dockerd[883]: at org.h2.message.DbException.getJdbcSQLException(DbException.java:345) ~[com.h2database.h2-1.4.188.jar:1.4.188]
Feb 01 17:47:40 nixos dockerd[883]: at org.h2.message.DbException.get(DbException.java:179) ~[com.h2database.h2-1.4.188.jar:1.4.188]
Feb 01 17:47:40 nixos dockerd[883]: at org.h2.message.DbException.get(DbException.java:155) ~[com.h2database.h2-1.4.188.jar:1.4.188]
Feb 01 17:47:40 nixos dockerd[883]: at org.h2.index.BaseIndex.getDuplicateKeyException(BaseIndex.java:102) ~[com.h2database.h2-1.4.188.jar:1.4.188]
Feb 01 17:47:40 nixos dockerd[883]: at org.h2.mvstore.db.MVSecondaryIndex.checkUnique(MVSecondaryIndex.java:231) ~[com.h2database.h2-1.4.188.jar:1.4.188]
Feb 01 17:47:40 nixos collins-intake-mysql-container-14-start[6097]: mysql-container-14 provisioning with nodeclass:databasenode primary_role:DATABASE by blake... SUCCESS
Feb 01 17:47:40 nixos collins-intake-mysql-container-14-start[6097]: + collins modify -C /nix/store/diyzwylw4dv42362vysbks5av57pjh0b-collins-cli.yaml -t mysql-container-14 -S Allocated:SPARE -r Provisioning -a HOSTNAME:mysql-conta
Feb 01 17:47:40 nixos collins-intake-mysql-container-11-start[6088]: mysql-container-11 changing status to MAINTENANCE:MAINT_NOOP... SUCCESS
Feb 01 17:47:40 nixos collins-intake-mysql-container-10-start[6095]: mysql-container-10 provisioning with nodeclass:databasenode primary_role:DATABASE by blake... SUCCESS
Feb 01 17:47:40 nixos collins-intake-mysql-container-11-start[6088]: + collins provision -C /nix/store/diyzwylw4dv42362vysbks5av57pjh0b-collins-cli.yaml -t mysql-container-11 -n databasenode -r DATABASE -b blake
@grahamc have you only been able to repro using the built-in H2 database, or with mysql as well?
I have also reproduced with mysql.
I'll need to allocate time to dig into the root cause here. Thanks for the report!
Sounds good. Let me know if I can help, likely soon I'll be able to open source the code used to cause the issue in the first place.
need to add transactional reads when verifying that a meta attribute exists
https://github.com/tumblr/collins/blob/master/conf/evolutions/collins/1.sql#L32
But this shouldn't be an issue in practice. Collins does create meta fields when they don't exist during asset creation. In practice this happens rarely. If you create an initial asset so that meta fields are created and then run any number in intakes at the same time, it won't be an issue.
I'd go to the extent of suggesting that this be considered a known issue, or implemented via a flag, blocking asset intake on account of validating asset meta existence has implication beyond the cases when asset meta needs to be created.
@maddalab does it need to be any asset, or a server asset in particular?
Hmm... @maddalab I gave it a try, loading in a server nearly identical to the rest of my assets, then once that finished doing parallel intake of many servers. However, I still found the problem.
Here is the script I'm running prior to intake:
URL="http://localhost:9000/api/asset"
TAG="bogus-server"
LLDP_FILE="single.lldp"
LSHW_FILE="virident.lshw"
curl --basic -X PUT -H "Accept: text/plain" \
-u blake:admin:first "$URL/$TAG"
curl --basic -H "Accept: text/plain" -u blake:admin:first \
--data-urlencode "lldp@$LLDP_FILE" \
--data-urlencode "lshw@$LSHW_FILE" \
--data-urlencode 'CHASSIS_TAG=bogus-server' \
"$URL/$TAG"
and then I run this for several nodes simultaneously (this is for #12, but I run this for 10, 11, and 12 in this case):
URL="http://localhost:9000/api/asset"
TAG="mysql-container-12"
LLDP_FILE="single.lldp"
LSHW_FILE="virident.lshw"
curl --basic -X PUT -H "Accept: text/plain" \
-u blake:admin:first "$URL/$TAG"
curl --basic -H "Accept: text/plain" -u blake:admin:first \
--data-urlencode "lldp@$LLDP_FILE" \
--data-urlencode "lshw@$LSHW_FILE" \
--data-urlencode 'CHASSIS_TAG=Testing this' \
"$URL/$TAG"
collins modify -C "collins-cli.yaml" -t "mysql-container-12" -S maintenance:maint_noop -r "Provisioning"
collins provision -C "collins-cli.yaml" -t "mysql-container-12" -n databasenode -r DATABASE -b blake
collins modify -C "collins-cli.yaml" -t "mysql-container-12" \
-S Allocated:SPARE \
-r "Provisioning" \
-a "HOSTNAME:mysql-container-12"
curl --basic -u blake:admin:first -X POST \
-d pool=DATABASE \
-d address=10.50.2.12 \
-d gateway=10.50.2.1 \
-d netmask=255.255.255.0 \
http://localhost:9000/api/asset/mysql-container-12/address
should this have fixed it? Here is the log, continuing to demonstrate the problem:
CLICK TO EXPAND
machine# [ 52.138779] systemd[1]: Starting Create a bogus collins asset to prepare the mysql asset columns...
machine# [ 52.175784] docker[3094]: 2017-06-02 14:44:11,953 - [WARN] - o.a.s.c.SolrCore - o.a.s.c.SolrCore:getSearcher:1761 - [collins] PERFORMANCE WARNING: Overlapping onDeckSearchers=2
machine# [ 52.176781] dockerd[1015]: 2017-06-02 14:44:11,953 - [WARN] - o.a.s.c.SolrCore - o.a.s.c.SolrCore:getSearcher:1761 - [collins] PERFORMANCE WARNING: Overlapping onDeckSearchers=2
machine# [ 52.183327] collins-stub-asset-for-meta-columns-start[3433]: % Total % Received % Xferd Average Speed Time Time Time Current
machine# [ 52.184106] collins-stub-asset-for-meta-columns-start[3433]: Dload Upload Total Spent Left Speed
machine: running command: systemctl --no-pager show 'default.target'
machine: exit status 0
machine: running command: systemctl list-jobs --full 2>&1
machine# [ 52.272428] dockerd[1015]: 2017-06-02 14:44:12,049 - [WARN] - SolrPlugin - p.a.LoggerLike$class:warn:112 - No items to index!
machine# [ 52.273177] docker[3094]: 2017-06-02 14:44:12,049 - [WARN] - SolrPlugin - p.a.LoggerLike$class:warn:112 - No items to index!
machine: exit status 0
100 318 100 318 0 0 2350 0 --:--:-- --:--:-- --:--:-- 2373
machine# [ 52.317820] collins-stub-asset-for-meta-columns-start[3433]: ASSET
machine# [ 52.318467] collins-stub-asset-for-meta-columns-start[3433]: ID 4
machine# [ 52.318829] collins-stub-asset-for-meta-columns-start[3433]: CREATED 2017-06-02T14:44:11
machine# [ 52.319310] collins-stub-asset-for-meta-columns-start[3433]: TAG bogus-server
machine# [ 52.319687] collins-stub-asset-for-meta-columns-start[3433]: STATUS Incomplete
machine# [ 52.320096] collins-stub-asset-for-meta-columns-start[3433]: DELETED null
machine# [ 52.320534] collins-stub-asset-for-meta-columns-start[3433]: UPDATED null
machine# [ 52.320850] collins-stub-asset-for-meta-columns-start[3433]: STATE null
machine# [ 52.321364] collins-stub-asset-for-meta-columns-start[3433]: TYPE SERVER_NODE
machine# [ 52.321690] collins-stub-asset-for-meta-columns-start[3433]: IPMI
machine# [ 52.322117] collins-stub-asset-for-meta-columns-start[3433]: IPMI_USERNAME root
machine# [ 52.322587] collins-stub-asset-for-meta-columns-start[3433]: ID 2
machine# [ 52.322956] collins-stub-asset-for-meta-columns-start[3433]: IPMI_ADDRESS 172.16.32.20
machine# [ 52.323465] collins-stub-asset-for-meta-columns-start[3433]: IPMI_NETMASK 255.255.240.0
machine# [ 52.323793] collins-stub-asset-for-meta-columns-start[3433]: ASSET_ID 4
machine# [ 52.324217] collins-stub-asset-for-meta-columns-start[3433]: ASSET_TAG bogus-server
machine# [ 52.324591] collins-stub-asset-for-meta-columns-start[3433]: IPMI_GATEWAY 172.16.32.1
machine# [ 52.324934] collins-stub-asset-for-meta-columns-start[3433]: IPMI_PASSWORD 4Ec2rHwPQiZYUl96
machine# [ 52.353222] collins-stub-asset-for-meta-columns-start[3433]: % Total % Received % Xferd Average Speed Time Time Time Current
machine# [ 52.353559] collins-stub-asset-for-meta-columns-start[3433]: Dload Upload Total Spent Left Speed
100 100k 100 13 100 100k 36 280k --:--:-- --:--:-- --:--:-- 281k
machine# [ 52.711394] collins-stub-asset-for-meta-columns-start[3433]: SUCCESS true
machine# [ 52.719450] systemd[1]: Started Create a bogus collins asset to prepare the mysql asset columns.
machine# [ 52.723006] systemd[1]: Starting Collins MySQL Node Intake: mysql-container-11...
machine# [ 52.724609] systemd[1]: Starting Collins MySQL Node Intake: mysql-container-10...
machine# [ 52.726539] systemd[1]: Starting Collins MySQL Node Intake: mysql-container-12...
machine# [ 52.764774] collins-intake-mysql-container-11-start[3461]: % Total % Received % Xferd Average Speed Time Time Time Current
machine# [ 52.765401] collins-intake-mysql-container-11-start[3461]: Dload Upload Total Spent Left Speed
machine# [ 52.775092] collins-intake-mysql-container-12-start[3467]: % Total % Received % Xferd Average Speed Time Time Time Current
machine# [ 52.775638] collins-intake-mysql-container-10-start[3463]: % Total % Received % Xferd Average Speed Time Time Time Current
machine# [ 52.776271] collins-intake-mysql-container-10-start[3463]: Dload Upload Total Spent Left Speed
machine# [ 52.779925] collins-intake-mysql-container-12-start[3467]: Dload Upload Total Spent Left Speed
100 330 100 330 0 0 2826 0 --:--:-- --:--:-- --:--:-- 2844
machine# [ 52.881306] collins-intake-mysql-container-11-start[3461]: ASSET
machine# [ 52.881867] collins-intake-mysql-container-11-start[3461]: ID 5
machine# [ 52.882449] collins-intake-mysql-container-11-start[3461]: CREATED 2017-06-02T14:44:12
machine# [ 52.882809] collins-intake-mysql-container-11-start[3461]: TAG mysql-container-11
machine# [ 52.883374] collins-intake-mysql-container-11-start[3461]: STATUS Incomplete
machine# [ 52.883731] collins-intake-mysql-container-11-start[3461]: DELETED null
machine# [ 52.884149] collins-intake-mysql-container-11-start[3461]: UPDATED null
machine# [ 52.884581] collins-intake-mysql-container-11-start[3461]: STATE null
machine# [ 52.884935] collins-intake-mysql-container-11-start[3461]: TYPE SERVER_NODE
machine# [ 52.885505] collins-intake-mysql-container-11-start[3461]: IPMI
machine# [ 52.885863] collins-intake-mysql-container-11-start[3461]: IPMI_USERNAME root
machine# [ 52.886488] collins-intake-mysql-container-11-start[3461]: ID 3
machine# [ 52.886898] collins-intake-mysql-container-11-start[3461]: IPMI_ADDRESS 172.16.32.21
machine# [ 52.887430] collins-intake-mysql-container-11-start[3461]: IPMI_NETMASK 255.255.240.0
machine# [ 52.887777] collins-intake-mysql-container-11-start[3461]: ASSET_ID 5
machine# [ 52.888170] collins-intake-mysql-container-11-start[3461]: ASSET_TAG mysql-container-11
machine# [ 52.888540] collins-intake-mysql-container-11-start[3461]: IPMI_GATEWAY 172.16.32.1
machine# [ 52.888910] collins-intake-mysql-container-11-start[3461]: IPMI_PASSWORD lKKOqFYgCxYogzUA
machine# [ 52.907441] dockerd[1015]: 2017-06-02 14:44:12,684 - [WARN] - o.a.s.c.SolrCore - o.a.s.c.SolrCore:getSearcher:1761 - [collins] PERFORMANCE WARNING: Overlapping onDeckSearchers=2
machine# [ 52.907962] docker[3094]: 2017-06-02 14:44:12,684 - [WARN] - o.a.s.c.SolrCore - o.a.s.c.SolrCore:getSearcher:1761 - [collins] PERFORMANCE WARNING: Overlapping onDeckSearchers=2
machine# [ 52.922601] docker[3094]: 2017-06-02 14:44:12,700 - [WARN] - o.a.s.c.SolrCore - o.a.s.c.SolrCore:getSearcher:1761 - [collins] PERFORMANCE WARNING: Overlapping onDeckSearchers=2
machine# [ 52.923251] dockerd[1015]: 2017-06-02 14:44:12,700 - [WARN] - o.a.s.c.SolrCore - o.a.s.c.SolrCore:getSearcher:1761 - [collins] PERFORMANCE WARNING: Overlapping onDeckSearchers=2
machine# [ 52.926890] collins-intake-mysql-container-11-start[3461]: % Total % Received % Xferd Average Speed Time Time Time Current
machine# [ 52.927498] collins-intake-mysql-container-11-start[3461]: Dload Upload Total Spent Left Speed
100 331 100 331 0 0 2071 0 --:--:-- --:--:-- --:--:-- 2081
machine# [ 52.934691] collins-intake-mysql-container-12-start[3467]: ASSET
machine# [ 52.935674] collins-intake-mysql-container-12-start[3467]: ID 7
machine# [ 52.936462] collins-intake-mysql-container-12-start[3467]: CREATED 2017-06-02T14:44:12
machine# [ 52.937210] collins-intake-mysql-container-12-start[3467]: TAG mysql-container-12
machine# [ 52.937805] collins-intake-mysql-container-12-start[3467]: STATUS Incomplete
machine# [ 52.938546] collins-intake-mysql-container-12-start[3467]: DELETED null
machine# [ 52.939199] collins-intake-mysql-container-12-start[3467]: UPDATED null
machine# [ 52.939832] collins-intake-mysql-container-12-start[3467]: STATE null
machine# [ 52.940615] collins-intake-mysql-container-12-start[3467]: TYPE SERVER_NODE
machine# [ 52.941251] collins-intake-mysql-container-12-start[3467]: IPMI
machine# [ 52.941694] collins-intake-mysql-container-12-start[3467]: IPMI_USERNAME root
machine# [ 52.942497] collins-intake-mysql-container-12-start[3467]: ID 16
machine# [ 52.943106] collins-intake-mysql-container-12-start[3467]: IPMI_ADDRESS 172.16.32.22
machine# [ 52.943649] collins-intake-mysql-container-12-start[3467]: IPMI_NETMASK 255.255.240.0
machine# [ 52.944247] collins-intake-mysql-container-12-start[3467]: ASSET_ID 7
machine# [ 52.944807] collins-intake-mysql-container-12-start[3467]: ASSET_TAG mysql-container-12
machine# [ 52.945511] collins-intake-mysql-container-12-start[3467]: IPMI_GATEWAY 172.16.32.1
machine# [ 52.946258] collins-intake-mysql-container-12-start[3467]: IPMI_PASSWORD WQ0RlMHz4zSuQDK7
machine# [ 52.972447] collins-intake-mysql-container-12-start[3467]: % Total % Received % Xferd Average Speed Time Time Time Current
machine# [ 52.972856] collins-intake-mysql-container-12-start[3467]: Dload Upload Total Spent Left Speed
machine# [ 52.985998] docker[3094]: 2017-06-02 14:44:12,763 - [WARN] - o.a.s.c.SolrCore - o.a.s.c.SolrCore:getSearcher:1761 - [collins] PERFORMANCE WARNING: Overlapping onDeckSearchers=2
machine# [ 52.986529] dockerd[1015]: 2017-06-02 14:44:12,763 - [WARN] - o.a.s.c.SolrCore - o.a.s.c.SolrCore:getSearcher:1761 - [collins] PERFORMANCE WARNING: Overlapping onDeckSearchers=2
100 331 100 331 0 0 1502 0 --:--:-- --:--:-- --:--:-- 1511
machine# [ 52.995401] collins-intake-mysql-container-10-start[3463]: ASSET
machine# [ 52.995774] collins-intake-mysql-container-10-start[3463]: ID 6
machine# [ 52.996182] collins-intake-mysql-container-10-start[3463]: CREATED 2017-06-02T14:44:12
machine# [ 52.996544] collins-intake-mysql-container-10-start[3463]: TAG mysql-container-10
machine# [ 52.996863] collins-intake-mysql-container-10-start[3463]: STATUS Incomplete
machine# [ 52.997462] collins-intake-mysql-container-10-start[3463]: DELETED null
machine# [ 52.997848] collins-intake-mysql-container-10-start[3463]: UPDATED null
machine# [ 52.998225] collins-intake-mysql-container-10-start[3463]: STATE null
machine# [ 52.998622] collins-intake-mysql-container-10-start[3463]: TYPE SERVER_NODE
machine# [ 52.999106] collins-intake-mysql-container-10-start[3463]: IPMI
machine# [ 52.999518] collins-intake-mysql-container-10-start[3463]: IPMI_USERNAME root
machine# [ 52.999904] collins-intake-mysql-container-10-start[3463]: ID 29
machine# [ 53.000385] collins-intake-mysql-container-10-start[3463]: IPMI_ADDRESS 172.16.32.23
machine# [ 53.000732] collins-intake-mysql-container-10-start[3463]: IPMI_NETMASK 255.255.240.0
machine# [ 53.001143] collins-intake-mysql-container-10-start[3463]: ASSET_ID 6
machine# [ 53.001470] collins-intake-mysql-container-10-start[3463]: ASSET_TAG mysql-container-10
machine# [ 53.001806] collins-intake-mysql-container-10-start[3463]: IPMI_GATEWAY 172.16.32.1
machine# [ 53.002227] collins-intake-mysql-container-10-start[3463]: IPMI_PASSWORD oUNsNMARrdwCHL7Z
machine# [ 53.027608] collins-intake-mysql-container-10-start[3463]: % Total % Received % Xferd Average Speed Time Time Time Current
machine# [ 53.027953] collins-intake-mysql-container-10-start[3463]: Dload Upload Total Spent Left Speed
100 100k 100 13 100 100k 66 517k --:--:-- --:--:-- --:--:-- 524k
machine# [ 53.118884] collins-intake-mysql-container-11-start[3461]: SUCCESS true
100 100k 100 13 100 100k 86 669k --:--:-- --:--:-- --:--:-- 671k
machine# [ 53.122888] collins-intake-mysql-container-12-start[3467]: SUCCESS true
100 100k 100 13 100 100k 86 666k --:--:-- --:--:-- --:--:-- 671k
machine# [ 53.178562] collins-intake-mysql-container-10-start[3463]: SUCCESS true
machine: running command: systemctl --no-pager show 'default.target'
machine: exit status 0
machine: running command: systemctl list-jobs --full 2>&1
machine: exit status 0
machine# [ 53.639273] dhcpcd[1499]: docker0: no IPv6 Routers available
machine# [ 54.064923] collins-intake-mysql-container-11-start[3461]: mysql-container-11 changing status to MAINTENANCE:MAINT_NOOP... SUCCESS
machine# [ 54.082840] dhcpcd[1499]: veth926ea7b: no IPv6 Routers available
machine# [ 54.107957] collins-intake-mysql-container-12-start[3467]: mysql-container-12 changing status to MAINTENANCE:MAINT_NOOP... SUCCESS
machine# [ 54.176486] collins-intake-mysql-container-10-start[3463]: mysql-container-10 changing status to MAINTENANCE:MAINT_NOOP... SUCCESS
machine: running command: systemctl --no-pager show 'default.target'
machine: exit status 0
machine: running command: systemctl list-jobs --full 2>&1
machine: exit status 0
machine# [ 55.130286] docker[3094]: 2017-06-02 14:44:14,907 - [WARN] - application - c.m.AssetLifecycle:collins$models$AssetLifecycle$$handleException:308 - Error saving attributes for asset
machine# [ 55.132341] docker[3094]: java.lang.RuntimeException: Exception while executing statement : Unique index or primary key violation: "CONSTRAINT_9D9B1_INDEX_F ON PUBLIC.ASSET_META(NAME) VALUES (CAST('SUFFIX' AS VARCHAR_IGNORECASE), 50)"; SQL statement:
machine# [ 55.133000] docker[3094]: insert into asset_meta (name, priority, value_type, description, label) values (?,?,?,?,?) [23505-188]
machine# [ 55.133702] docker[3094]: errorCode: 23505, sqlState: 23505
machine# [ 55.134120] docker[3094]: insert into asset_meta (name, priority, value_type, description, label) values (?,?,?,?,?)
machine# [ 55.134680] docker[3094]: jdbcParams:[SUFFIX,-1,1,SUFFIX,Suffix]
machine# [ 55.135310] docker[3094]: at org.squeryl.internals.DatabaseAdapter$class._exec(DatabaseAdapter.scala:297) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
machine# [ 55.135767] docker[3094]: at org.squeryl.internals.DatabaseAdapter$class.exec(DatabaseAdapter.scala:349) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
machine# [ 55.136492] docker[3094]: at org.squeryl.adapters.H2Adapter.exec(H2Adapter.scala:22) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
machine# [ 55.136995] docker[3094]: at org.squeryl.internals.DatabaseAdapter$class.executeUpdateForInsert(DatabaseAdapter.scala:383) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
machine# [ 55.137544] docker[3094]: at org.squeryl.adapters.H2Adapter.executeUpdateForInsert(H2Adapter.scala:22) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
machine# [ 55.138087] docker[3094]: Caused by: org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: "CONSTRAINT_9D9B1_INDEX_F ON PUBLIC.ASSET_META(NAME) VALUES (CAST('SUFFIX' AS VARCHAR_IGNORECASE), 50)"; SQL statement:
machine# [ 55.138680] docker[3094]: insert into asset_meta (name, priority, value_type, description, label) values (?,?,?,?,?) [23505-188]
machine# [ 55.139115] docker[3094]: at org.h2.message.DbException.getJdbcSQLException(DbException.java:345) ~[com.h2database.h2-1.4.188.jar:1.4.188]
machine# [ 55.139599] docker[3094]: at org.h2.message.DbException.get(DbException.java:179) ~[com.h2database.h2-1.4.188.jar:1.4.188]
machine# [ 55.140244] docker[3094]: at org.h2.message.DbException.get(DbException.java:155) ~[com.h2database.h2-1.4.188.jar:1.4.188]
machine# [ 55.140676] docker[3094]: at org.h2.index.BaseIndex.getDuplicateKeyException(BaseIndex.java:102) ~[com.h2database.h2-1.4.188.jar:1.4.188]
machine# [ 55.141362] docker[3094]: at org.h2.mvstore.db.MVSecondaryIndex.checkUnique(MVSecondaryIndex.java:231) ~[com.h2database.h2-1.4.188.jar:1.4.188]
machine# [ 55.141816] docker[3094]: 2017-06-02 14:44:14,907 - [WARN] - application - c.m.AssetLifecycle:collins$models$AssetLifecycle$$handleException:308 - Error saving attributes for asset
machine# [ 55.142477] docker[3094]: java.lang.RuntimeException: Exception while executing statement : Unique index or primary key violation: "CONSTRAINT_9D9B1_INDEX_F ON PUBLIC.ASSET_META(NAME) VALUES (CAST('SUFFIX' AS VARCHAR_IGNORECASE), 50)"; SQL statement:
machine# [ 55.143151] docker[3094]: insert into asset_meta (name, priority, value_type, description, label) values (?,?,?,?,?) [23505-188]
machine# [ 55.143447] docker[3094]: errorCode: 23505, sqlState: 23505
machine# [ 55.143806] docker[3094]: insert into asset_meta (name, priority, value_type, description, label) values (?,?,?,?,?)
machine# [ 55.144476] docker[3094]: jdbcParams:[SUFFIX,-1,1,SUFFIX,Suffix]
machine# [ 55.144987] docker[3094]: at org.squeryl.internals.DatabaseAdapter$class._exec(DatabaseAdapter.scala:297) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
machine# [ 55.145519] docker[3094]: at org.squeryl.internals.DatabaseAdapter$class.exec(DatabaseAdapter.scala:349) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
machine# [ 55.146169] docker[3094]: at org.squeryl.adapters.H2Adapter.exec(H2Adapter.scala:22) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
machine# [ 55.146694] docker[3094]: at org.squeryl.internals.DatabaseAdapter$class.executeUpdateForInsert(DatabaseAdapter.scala:383) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
machine# [ 55.147289] docker[3094]: at org.squeryl.adapters.H2Adapter.executeUpdateForInsert(H2Adapter.scala:22) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
machine# [ 55.147729] docker[3094]: Caused by: org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: "CONSTRAINT_9D9B1_INDEX_F ON PUBLIC.ASSET_META(NAME) VALUES (CAST('SUFFIX' AS VARCHAR_IGNORECASE), 50)"; SQL statement:
machine# [ 55.148252] docker[3094]: insert into asset_meta (name, priority, value_type, description, label) values (?,?,?,?,?) [23505-188]
machine# [ 55.148523] docker[3094]: at org.h2.message.DbException.getJdbcSQLException(DbException.java:345) ~[com.h2database.h2-1.4.188.jar:1.4.188]
machine# [ 55.148950] docker[3094]: at org.h2.message.DbException.get(DbException.java:179) ~[com.h2database.h2-1.4.188.jar:1.4.188]
machine# [ 55.149481] docker[3094]: at org.h2.message.DbException.get(DbException.java:155) ~[com.h2database.h2-1.4.188.jar:1.4.188]
machine# [ 55.150169] dockerd[1015]: 2017-06-02 14:44:14,907 - [WARN] - application - c.m.AssetLifecycle:collins$models$AssetLifecycle$$handleException:308 - Error saving attributes for asset
machine# [ 55.150628] docker[3094]: at org.h2.index.BaseIndex.getDuplicateKeyException(BaseIndex.java:102) ~[com.h2database.h2-1.4.188.jar:1.4.188]
machine# [ 55.151179] docker[3094]: at org.h2.mvstore.db.MVSecondaryIndex.checkUnique(MVSecondaryIndex.java:231) ~[com.h2database.h2-1.4.188.jar:1.4.188]
machine# [ 55.151650] dockerd[1015]: java.lang.RuntimeException: Exception while executing statement : Unique index or primary key violation: "CONSTRAINT_9D9B1_INDEX_F ON PUBLIC.ASSET_META(NAME) VALUES (CAST('SUFFIX' AS VARCHAR_IGNORECASE), 50)"; SQL statement:
machine# [ 55.152281] dockerd[1015]: insert into asset_meta (name, priority, value_type, description, label) values (?,?,?,?,?) [23505-188]
machine# [ 55.152812] dockerd[1015]: errorCode: 23505, sqlState: 23505
machine# [ 55.153631] dockerd[1015]: insert into asset_meta (name, priority, value_type, description, label) values (?,?,?,?,?)
machine# [ 55.153983] dockerd[1015]: jdbcParams:[SUFFIX,-1,1,SUFFIX,Suffix]
machine# [ 55.154667] dockerd[1015]: at org.squeryl.internals.DatabaseAdapter$class._exec(DatabaseAdapter.scala:297) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
machine# [ 55.182218] dockerd[1015]: at org.squeryl.internals.DatabaseAdapter$class.exec(DatabaseAdapter.scala:349) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
machine# [ 55.182756] dockerd[1015]: at org.squeryl.adapters.H2Adapter.exec(H2Adapter.scala:22) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
machine# [ 55.183295] dockerd[1015]: at org.squeryl.internals.DatabaseAdapter$class.executeUpdateForInsert(DatabaseAdapter.scala:383) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
machine# [ 55.183870] dockerd[1015]: at org.squeryl.adapters.H2Adapter.executeUpdateForInsert(H2Adapter.scala:22) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
machine# [ 55.184558] dockerd[1015]: Caused by: org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: "CONSTRAINT_9D9B1_INDEX_F ON PUBLIC.ASSET_META(NAME) VALUES (CAST('SUFFIX' AS VARCHAR_IGNORECASE), 50)"; SQL statement:
machine# [ 55.185174] dockerd[1015]: insert into asset_meta (name, priority, value_type, description, label) values (?,?,?,?,?) [23505-188]
machine# [ 55.185744] dockerd[1015]: at org.h2.message.DbException.getJdbcSQLException(DbException.java:345) ~[com.h2database.h2-1.4.188.jar:1.4.188]
machine# [ 55.186543] dockerd[1015]: at org.h2.message.DbException.get(DbException.java:179) ~[com.h2database.h2-1.4.188.jar:1.4.188]
machine# [ 55.187160] dockerd[1015]: at org.h2.message.DbException.get(DbException.java:155) ~[com.h2database.h2-1.4.188.jar:1.4.188]
machine# [ 55.187702] dockerd[1015]: at org.h2.index.BaseIndex.getDuplicateKeyException(BaseIndex.java:102) ~[com.h2database.h2-1.4.188.jar:1.4.188]
machine# [ 55.188059] dockerd[1015]: at org.h2.mvstore.db.MVSecondaryIndex.checkUnique(MVSecondaryIndex.java:231) ~[com.h2database.h2-1.4.188.jar:1.4.188]
machine# [ 55.188653] dockerd[1015]: 2017-06-02 14:44:14,907 - [WARN] - application - c.m.AssetLifecycle:collins$models$AssetLifecycle$$handleException:308 - Error saving attributes for asset
machine# [ 55.188989[ 55.742094] serial8250: too much work for irq4
machine# ] dockerd[1015]: java.lang.RuntimeException: Exception while executing statement : Unique index or primary key violation: "CONSTRAINT_9D9B1_INDEX_F ON PUBLIC.ASSET_META(NAME) VALUES (CAST('SUFFIX' AS VARCHAR_IGNORECASE), 50)"; SQL statement:
machine# [ 55.189636] dockerd[1015]: insert into asset_meta (name, priority, value_type, description, label) values (?,?,?,?,?) [23505-188]
machine# [ 55.190032] dockerd[1015]: errorCode: 23505, sqlState: 23505
machine# [ 55.190663] dockerd[1015]: insert into asset_meta (name, priority, value_type, description, label) values (?,?,?,?,?)
machine# [ 55.191257] dockerd[1015]: jdbcParams:[SUFFIX,-1,1,SUFFIX,Suffix]
machine# [ 55.191815] dockerd[1015]: at org.squeryl.internals.DatabaseAdapter$class._exec(DatabaseAdapter.scala:297) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
machine# [ 55.192294] dockerd[1015]: at org.squeryl.internals.DatabaseAdapter$class.exec(DatabaseAdapter.scala:349) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
machine# [ 55.192618] dockerd[1015]: at org.squeryl.adapters.H2Adapter.exec(H2Adapter.scala:22) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
machine# [ 55.193165] dockerd[1015]: at org.squeryl.internals.DatabaseAdapter$class.executeUpdateForInsert(DatabaseAdapter.scala:383) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
machine# [ 55.193701] dockerd[1015]: at org.squeryl.adapters.H2Adapter.executeUpdateForInsert(H2Adapter.scala:22) ~[org.squeryl.squeryl_2.11-0.9.5-7.jar:0.9.5-7]
machine# [ 55.194346] dockerd[1015]: Caused by: org.h2.jdbc.JdbcSQLException: Unique index or primary key violation: "CONSTRAINT_9D9B1_INDEX_F ON PUBLIC.ASSET_META(NAME) VALUES (CAST('SUFFIX' AS VARCHAR_IGNORECASE), 50)"; SQL statement:
machine# [ 55.194650] dockerd[1015]: insert into asset_meta (name, priority, value_type, description, label) values (?,?,?,?,?) [23505-188]
machine# [ 55.195062] dockerd[1015]: at org.h2.message.DbException.getJdbcSQLException(DbException.java:345) ~[com.h2database.h2-1.4.188.jar:1.4.188]
machine# [ 55.195331] dockerd[1015]: at org.h2.message.DbException.get(DbException.java:179) ~[com.h2database.h2-1.4.188.jar:1.4.188]
machine# [ 55.195746] dockerd[1015]: at org.h2.message.DbException.get(DbException.java:155) ~[com.h2database.h2-1.4.188.jar:1.4.188]
machine# [ 55.196338] dockerd[1015]: at org.h2.index.BaseIndex.getDuplicateKeyException(BaseIndex.java:102) ~[com.h2database.h2-1.4.188.jar:1.4.188]
machine# [ 55.196682] dockerd[1015]: at org.h2.mvstore.db.MVSecondaryIndex.checkUnique(MVSecondaryIndex.java:231) ~[com.h2database.h2-1.4.188.jar:1.4.188]