search

cloudfoundry-incubator / admin-ui

Need new main contributor - An application for viewing Cloud Foundry metrics and operations data.
Apache License 2.0
71 stars 44 forks source link

Error pulling events when using MySQL for CCDB #141

Closed amhuber closed 9 years ago

amhuber commented 9 years ago

I'm getting the following error when moving to a newer version of AdminUI that pulls events:

D, [2015-06-17T09:32:22.982008 #2480] DEBUG -- : [ -- ] : [ -- ] : Select for key events, table events: SELECT `actee`, `actee_name`, `actee_type`, `actor`, `actor_name`, `actor_type`, `created_at`, `guid`, `id`, `metadata`, `organization_guid`, `space_guid`, `space_id`, `timestamp`, `type`, `updated_at` FROM `events` WHERE ("timestamp" >= CURRENT_TIMESTAMP - INTERVAL '7 DAYS')
D, [2015-06-17T09:32:22.982061 #2480] DEBUG -- : [ -- ] : [ -- ] : Columns removed for key events, table events: []
D, [2015-06-17T09:32:22.983412 #2480] DEBUG -- : [ -- ] : [ -- ] : Error during discovery of events: #<Sequel::DatabaseError: Mysql2::Error: You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near ')' at line 1>
D, [2015-06-17T09:32:22.983513 #2480] DEBUG -- : [ -- ] : [ -- ] : /usr/local/rvm/gems/ruby-1.9.3-p551/gems/sequel-4.23.0/lib/sequel/adapters/mysql2.rb:78:in `query'
/usr/local/rvm/gems/ruby-1.9.3-p551/gems/sequel-4.23.0/lib/sequel/adapters/mysql2.rb:78:in `block in _execute'
/usr/local/rvm/gems/ruby-1.9.3-p551/gems/sequel-4.23.0/lib/sequel/database/logging.rb:33:in `log_yield'
/usr/local/rvm/gems/ruby-1.9.3-p551/gems/sequel-4.23.0/lib/sequel/adapters/mysql2.rb:78:in `_execute'
/usr/local/rvm/gems/ruby-1.9.3-p551/gems/sequel-4.23.0/lib/sequel/adapters/shared/mysql_prepared_statements.rb:34:in `block in execute'
/usr/local/rvm/gems/ruby-1.9.3-p551/gems/sequel-4.23.0/lib/sequel/database/connecting.rb:250:in `block in synchronize'
/usr/local/rvm/gems/ruby-1.9.3-p551/gems/sequel-4.23.0/lib/sequel/connection_pool/threaded.rb:103:in `hold'
/usr/local/rvm/gems/ruby-1.9.3-p551/gems/sequel-4.23.0/lib/sequel/database/connecting.rb:250:in `synchronize'
/usr/local/rvm/gems/ruby-1.9.3-p551/gems/sequel-4.23.0/lib/sequel/adapters/shared/mysql_prepared_statements.rb:34:in `execute'
/usr/local/rvm/gems/ruby-1.9.3-p551/gems/sequel-4.23.0/lib/sequel/dataset/actions.rb:921:in `execute'
/usr/local/rvm/gems/ruby-1.9.3-p551/gems/sequel-4.23.0/lib/sequel/adapters/mysql2.rb:195:in `execute'
/usr/local/rvm/gems/ruby-1.9.3-p551/gems/sequel-4.23.0/lib/sequel/adapters/mysql2.rb:154:in `fetch_rows'
/usr/local/rvm/gems/ruby-1.9.3-p551/gems/sequel-4.23.0/lib/sequel/dataset/actions.rb:139:in `each'
/usr/local/rvm/gems/ruby-1.9.3-p551/gems/sequel-4.23.0/lib/sequel/database/dataset.rb:46:in `fetch'
/home/adminui/app/admin-ui/lib/admin/cc.rb:640:in `block in select'
/usr/local/rvm/gems/ruby-1.9.3-p551/gems/sequel-4.23.0/lib/sequel/database/connecting.rb:69:in `connect'
/usr/local/rvm/gems/ruby-1.9.3-p551/gems/sequel-4.23.0/lib/sequel/core.rb:95:in `connect'
/home/adminui/app/admin-ui/lib/admin/cc.rb:610:in `select'
/home/adminui/app/admin-ui/lib/admin/cc.rb:550:in `discover'
/home/adminui/app/admin-ui/lib/admin/cc.rb:578:in `block in schedule'
/home/adminui/app/admin-ui/lib/admin/scheduled_thread_pool.rb:27:in `call'
/home/adminui/app/admin-ui/lib/admin/scheduled_thread_pool.rb:27:in `block (2 levels) in initialize'

It looks like the SQL syntax being generated is invalid for MySQL.

Aaron Huber Intel Corporation

rboykin commented 9 years ago

@amhuber, I determined a fix and will commit a change tomorrow to address.

rboykin commented 9 years ago

@amhuber, please try commit https://github.com/cloudfoundry-incubator/admin-ui/commit/f18e2465f1fef38dd110cd684123611951c75582

amhuber commented 9 years ago

Well, that did fix the error but it still doesn't seem to be working. Now it just says there are 0 events:

D, [2015-06-18T10:08:51.124115 #7192] DEBUG -- : [ -- ] : [ -- ] : [150 second interval] Starting view model events discovery...
D, [2015-06-18T10:08:51.124174 #7192] DEBUG -- : [ -- ] : [ -- ] : Caching view model events data.  Compilation time: 1.5474e-05 seconds
D, [2015-06-18T10:08:51.199199 #7192] DEBUG -- : [ -- ] : [ -- ] : [300 second interval] Starting CC events discovery...
D, [2015-06-18T10:08:51.228147 #7192] DEBUG -- : [ -- ] : [ -- ] : Select for key events, table events: SELECT `actee`, `actee_name`, `actee_type`, `actor`, `actor_name`, `actor_type`, `created_at`, `guid`, `id`, `metadata`, `organization_guid`, `space_guid`, `space_id`, `timestamp`, `type`, `updated_at` FROM `events` WHERE "timestamp" >= CURRENT_TIMESTAMP - INTERVAL '7' DAY
D, [2015-06-18T10:08:51.228221 #7192] DEBUG -- : [ -- ] : [ -- ] : Columns removed for key events, table events: []
D, [2015-06-18T10:08:51.230138 #7192] DEBUG -- : [ -- ] : [ -- ] : Caching CC events data.  Count: 0.  Retrieval time: 0.030858964 seconds
D, [2015-06-18T10:09:01.148820 #7192] DEBUG -- : [ -- ] : [ -- ] : [150 second interval] Starting view model events discovery...
D, [2015-06-18T10:09:01.148918 #7192] DEBUG -- : [ -- ] : [ -- ] : Caching view model events data.  Compilation time: 4.0182e-05 seconds
D, [2015-06-18T10:11:31.199176 #7192] DEBUG -- : [ -- ] : [ -- ] : [150 second interval] Starting view model events discovery...
D, [2015-06-18T10:11:31.199269 #7192] DEBUG -- : [ -- ] : [ -- ] : Caching view model events data.  Compilation time: 4.9348e-05 seconds
D, [2015-06-18T10:13:51.540473 #7192] DEBUG -- : [ -- ] : [ -- ] : [300 second interval] Starting CC events discovery...
D, [2015-06-18T10:13:51.559106 #7192] DEBUG -- : [ -- ] : [ -- ] : Caching CC events data.  Count: 0.  Retrieval time: 0.018569781 seconds
D, [2015-06-18T10:14:01.234742 #7192] DEBUG -- : [ -- ] : [ -- ] : [150 second interval] Starting view model events discovery...
D, [2015-06-18T10:14:01.234840 #7192] DEBUG -- : [ -- ] : [ -- ] : Caching view model events data.  Compilation time: 5.3178e-05 seconds
D, [2015-06-18T10:16:31.272851 #7192] DEBUG -- : [ -- ] : [ -- ] : [150 second interval] Starting view model events discovery...
D, [2015-06-18T10:16:31.272993 #7192] DEBUG -- : [ -- ] : [ -- ] : Caching view model events data.  Compilation time: 5.3608e-05 seconds

I tested the query manually from the mysql client and I do get records:

mysql> set session sql_mode = 'ANSI';
Query OK, 0 rows affected (0.01 sec)

SELECT `actee`, `actee_name`, `actee_type`, `actor`, `actor_name`, `actor_type`, `created_at`, `guid`, `id`, `metadata`, `organization_guid`, `space_guid`, `space_id`, `timestamp`, `type`, `updated_at` FROM `events` WHERE "timestamp" >= CURRENT_TIMESTAMP - INTERVAL '7' DAY;
<data>
2178 rows in set (0.10 sec)

I'll poke through the code to see if I can find anything.

Aaron

amhuber commented 9 years ago

Here is one row of data in case that helps:

mysql> SELECT `actee`, `actee_name`, `actee_type`, `actor`, `actor_name`, `actor_type`, `created_at`, `guid`, `id`, `metadata`, `organization_guid`, `space_guid`, `space_id`, `timestamp`, `type`, `updated_at` FROM `events` WHERE "timestamp" >= CURRENT_TIMESTAMP - INTERVAL '7' DAY LIMIT 1;
+--------------------------------------+-------------+------------+--------------------------------------+------------+------------+---------------------+--------------------------------------+----+-----------------------------------------------------------------------------------------------+--------------------------------------+--------------------------------------+----------+---------------------+--------------------+------------+
| actee                                | actee_name  | actee_type | actor                                | actor_name | actor_type | created_at          | guid                                 | id | metadata                                                                                      | organization_guid                    | space_guid                           | space_id | timestamp           | type               | updated_at |
+--------------------------------------+-------------+------------+--------------------------------------+------------+------------+---------------------+--------------------------------------+----+-----------------------------------------------------------------------------------------------+--------------------------------------+--------------------------------------+----------+---------------------+--------------------+------------+
| 60e26603-661a-4957-8223-ece0d17a9e0c | Development | space      | 032ec221-8eb3-4652-a021-7be438c2732e | admin      | user       | 2015-06-12 11:25:36 | 488c7e58-fda7-4464-9538-8bf683ce9a18 |  2 | {"request":{"name":"Development","organization_guid":"8a84b780-c82f-4968-8a79-62cfa389f85f"}} | 8a84b780-c82f-4968-8a79-62cfa389f85f | 60e26603-661a-4957-8223-ece0d17a9e0c |        2 | 2015-06-12 18:25:36 | audit.space.create | NULL       |
+--------------------------------------+-------------+------------+--------------------------------------+------------+------------+---------------------+--------------------------------------+----+-----------------------------------------------------------------------------------------------+--------------------------------------+--------------------------------------+----------+---------------------+--------------------+------------+
1 row in set (0.00 sec)

Aaron

amhuber commented 9 years ago

Just did some testing with the Sequel gem, looks like this is just due to the quoting around the field name in the where clause:

require 'sequel'

items = []

Sequel.connect('mysql2://<snip>') do |connection|
  #Doesn't work
  #connection.fetch("SELECT `actee`, `actee_name`, `actee_type`, `actor`, `actor_name`, `actor_type`, `created_at`, `guid`, `id`, `metadata`, `organization_guid`, `space_guid`, `space_id`, `timestamp`, `type`, `updated_at` FROM `events` WHERE \"timestamp\" >= CURRENT_TIMESTAMP - INTERVAL '1' DAY") do |row|

  #Works
  connection.fetch("SELECT `actee`, `actee_name`, `actee_type`, `actor`, `actor_name`, `actor_type`, `created_at`, `guid`, `id`, `metadata`, `organization_guid`, `space_guid`, `space_id`, `timestamp`, `type`, `updated_at` FROM `events` WHERE `timestamp` >= CURRENT_TIMESTAMP - INTERVAL '1' DAY") do |row|
    items.push(row)
  end
end

print items.count

I also tried a single quote and it didn't work either. It worked with either no quotes or with the back-tick character.

Bad:

\"timestamp\"
'timestamp'

Good:

`timestamp`
timestamp

Now hopefully you can find one that works for Postgres as well. :-)

Aaron

amhuber commented 9 years ago

Just a final confirmation, everything works as expected when I used backticks in the code:

where:   "`timestamp` >= CURRENT_TIMESTAMP - INTERVAL '#{@config.event_days}' DAY"

Log entry:

D, [2015-06-18T11:07:23.809563 #11193] DEBUG -- : [ -- ] : [ -- ] : Caching CC events data.  Count: 2178.  Retrieval time: 0.150513388 seconds

Page view looks good, etc.

Aaron

rboykin commented 9 years ago

@amhuber, back tick does not work with Postgres. But, no quote around timestamp appears to work. I'll run through the rspec tests and do some more freelance testing to make sure.

amhuber commented 9 years ago

Taking the back ticks out works fine on MySQL as well, just did a full test:

D, [2015-06-18T11:26:27.540424 #13120] DEBUG -- : [ -- ] : [ -- ] : Caching CC events data.  Count: 2178.  Retrieval time: 0.261141404 seconds
rboykin commented 9 years ago

@amhuber, thanks for the legwork. Here is a commit to remove the quotes from around timestamp in the events predicate: https://github.com/cloudfoundry-incubator/admin-ui/commit/9802863167dadb22d294b37c1722f9467b8cb5fb

amhuber commented 9 years ago

Confirmed working, thanks!