stacktrace on heat stack-delete complaining about isotime()

[Sam Yaple]

Creating a stack works fine, however on delete heat-engine throws the following stacktrace and never actually deletes the stack. The client receives no errors since all the api calls are good.

2015-08-26 06:31:11.589 19 DEBUG heat.engine.stack_lock [-] Engine d06ec187-06a5-44f3-967d-aeedb3f783a5 released lock on stack 4df8920b-f90b-4653-a09d-75cfcb7a51cd release /usr/lib/python2.7/dist-packages/heat/engine/stack_lock.py:124
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/eventlet/hubs/hub.py", line 457, in fire_timers
    timer()
  File "/usr/lib/python2.7/dist-packages/eventlet/hubs/timer.py", line 58, in __call__
    cb(*args, **kw)
  File "/usr/lib/python2.7/dist-packages/eventlet/greenthread.py", line 214, in main
    result = function(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/heat/engine/service.py", line 116, in _start_with_trace
    return func(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/osprofiler/profiler.py", line 105, in wrapper
    return f(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/heat/engine/stack.py", line 1365, in delete
    action)
  File "/usr/lib/python2.7/dist-packages/osprofiler/profiler.py", line 105, in wrapper
    return f(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/heat/engine/stack.py", line 711, in state_set
    notification.send(self)
  File "/usr/lib/python2.7/dist-packages/heat/engine/notification/stack.py", line 39, in send
    engine_api.format_notification_body(stack))
  File "/usr/lib/python2.7/dist-packages/heat/engine/api.py", line 284, in format_notification_body
    rpc_api.NOTIFY_CREATE_AT: stack.created_time.isoformat(),
AttributeError: 'NoneType' object has no attribute 'isoformat'

This was installed from source against latest master for Heat using Kolla. It is always reproduce-able.

I can provide additional information if requested.

[Angus Salkeld (asalkeld)]

This seems to have caused a regression:
https://github.com/openstack/heat/commit/720c86549a05d044ecdf7d4ad3761db4dba1a88e

timeutils.isotime() used to check for None, now we don't.
see: https://github.com/openstack/oslo.utils/blob/master/oslo_utils/timeutils.py#L51

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/217058

[Thomas Herve (therve)]

Not yet convinced this is a regression. We need more information.

[Sam Yaple (s8m)]

I find this highly unlikely to be related to that patch asalkeld after 6 hours of debugging. Down to the database fetch I have seen the database have the 'created_at' field while the object returned to be has 'created_at' set to None.

Will continue to investigate.

[Sam Yaple (s8m)]

Tracked down to a migration that occurs for for a feature that MariaDB 10 does not support yet. I have updated the patch above https://review.openstack.org/217058

That filters version of MariaDB greater that 10

[Steve Baker (steve-stevebaker)]

Sam, are you running against distro packages for the python dependencies, or the pip dependencies from heat/requirements.txt?

[Sam Yaple (s8m)]

Hello Steve,

I am installing pip dependencies in a fresh clean container.

After more testing I have discovered this occurs no matter what version of MariaDB 10 is used, even though the database correctly records the time to 6 places after the second. Preventing the database migration does resolve this issue for me, but I have a feeling it is a deeper issues. My working theory at this moment is it is a dependency issue.

[Sam Yaple (s8m)]

https://github.com/openstack/heat/blob/master/heat/engine/stack.py#L491
created_at time is set correct, it is stored in the database incorrectly (not storing microseconds)

> /usr/lib/python2.7/dist-packages/heat/engine/stack.py(493)store()
(Pdb) new_s.__dict__
{'username': u'admin', '_context': <heat.common.context.RequestContext object at 0x7f3728155e90>, 'updated_at': None, 'prev_raw_template_id': None, '_changed_fields': set([]), 'deleted_at': None, 'id': '81512b6b-ea3e-4a45-b950-716c58b42835', 'current_traversal': None, 'parent_resource_name': None, 'current_deps': None, 'raw_template': RawTemplate(environment=<?>,files=<?>,id=<?>,template=<?>), 'status': 'IN_PROGRESS', 'disable_rollback': True, 'tags': None, 'stack_user_project_id': None, 'convergence': False, 'raw_template_id': 13L, 'status_reason': '', 'tenant': u'b56e30034f014cbd8ba324a4f502502c', 'prev_raw_template': None, 'name': u'testaasddd', 'nested_depth': 0, 'created_at': datetime.datetime(2015, 8, 27, 7, 48, 11, 758098), 'user_creds_id': u'13', 'timeout': None, 'action': 'CREATE', 'owner_id': None, 'backup': False}

mysql> select * from stack where id='81512b6b-ea3e-4a45-b950-716c58b42835' \G
*************************** 1. row ***************************
                   id: 81512b6b-ea3e-4a45-b950-716c58b42835
           created_at: 2015-08-27 07:48:11.000000
           updated_at: NULL
           deleted_at: NULL
                 name: testaasddd
      raw_template_id: 13
        user_creds_id: 13
             username: admin
             owner_id: NULL
               action: CREATE
               status: IN_PROGRESS
        status_reason:
              timeout: NULL
               tenant: b56e30034f014cbd8ba324a4f502502c
     disable_rollback: 1
stack_user_project_id: NULL
               backup: 0
         nested_depth: 0
          convergence: 0
 prev_raw_template_id: NULL
    current_traversal: NULL
         current_deps: null
 parent_resource_name: NULL
1 row in set (0.00 sec)

[OpenStack Infra (hudson-openstack)]

Change abandoned by Sam Yaple (<email address hidden>) on branch: master
Review: https://review.openstack.org/217058
Reason: While this does prevent the issue from occurring, this is not the issue. I am abandoning this change. I will submit a new patchset if i ever figure it out (and it is related to heat)

[Sam Yaple (s8m)]

This occurs with MariaDB 10.0.18 and up (i did not test previous version, they are probably affected to) and I doubt it is related to MariaDB itself since I can probably set microseconds if I update the database by hand.

I tried a range of different dependency versions for oslo.db, oslo_versionedobjects, sqlalchemy but everything acted the same way.

The pdb session info along with the mysql output is all I am able to contribute at this point. I am open for suggestions and I will help in anyway to track down this issue, but I am all out of ideas.

[Steve Baker (steve-stevebaker)]

You can log the actual insert query by setting the following in /etc/heat/heat.conf:

[database]
connection_debug = 50

then restarting heat-engine

[Sam Yaple (s8m)]

The logs seem to indicate that is is updated correctly:

2015-08-28 08:20:27.758 23 INFO sqlalchemy.engine.base.Engine [req-70392def-f8ab-45cf-b4f9-b913d8a90933 admin admin] SELECT 1
2015-08-28 08:20:27.758 23 INFO sqlalchemy.engine.base.Engine [req-70392def-f8ab-45cf-b4f9-b913d8a90933 admin admin] ()
2015-08-28 08:20:27.759 23 INFO sqlalchemy.engine.base.Engine [req-70392def-f8ab-45cf-b4f9-b913d8a90933 admin admin] BEGIN (implicit)
2015-08-28 08:20:27.760 23 INFO sqlalchemy.engine.base.Engine [req-70392def-f8ab-45cf-b4f9-b913d8a90933 admin admin] INSERT INTO user_creds (created_at, updated_at, username, password, region_name, decrypt_method, tenant, auth_url, tenant_id, trust_id, trustor_user_id) VALUES (%s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s)
2015-08-28 08:20:27.760 23 INFO sqlalchemy.engine.base.Engine [req-70392def-f8ab-45cf-b4f9-b913d8a90933 admin admin] (datetime.datetime(2015, 8, 28, 8, 20, 27, 759976), None, None, None, None, 'cryptography_decrypt_v1', 'admin', 'http://192.168.31.10:5000/v2.0', 'cedcac1041224d0db4d77b223b16033c', 'gAAAAABV4BnL5Qrk0PLVhoNjxeRNs5tVCKdc_bnNHNMl5zmX9gWWAhGzqQ10ztpyu_axxrPGLC1oDSOm2KBUuKIh1VuTHMp4tvy3gyIwOSuJtMFy2_xOOl2r9VtneX1IIa8ZpKkJQ5Cb', 'ef1a7d0d7835401aae9095f8c5f5ba5a')
2015-08-28 08:20:27.761 23 INFO sqlalchemy.engine.base.Engine [req-70392def-f8ab-45cf-b4f9-b913d8a90933 admin admin] COMMIT
2015-08-28 08:20:27.773 23 INFO sqlalchemy.engine.base.Engine [req-70392def-f8ab-45cf-b4f9-b913d8a90933 admin admin] SELECT 1
2015-08-28 08:20:27.773 23 INFO sqlalchemy.engine.base.Engine [req-70392def-f8ab-45cf-b4f9-b913d8a90933 admin admin] ()
2015-08-28 08:20:27.774 23 INFO sqlalchemy.engine.base.Engine [req-70392def-f8ab-45cf-b4f9-b913d8a90933 admin admin] BEGIN (implicit)
2015-08-28 08:20:27.775 23 INFO sqlalchemy.engine.base.Engine [req-70392def-f8ab-45cf-b4f9-b913d8a90933 admin admin] INSERT INTO stack (created_at, deleted_at, action, status, status_reason, id, name, raw_template_id, prev_raw_template_id, username, tenant, user_creds_id, owner_id, parent_resource_name, timeout, disable_rollback, stack_user_project_id, backup, nested_depth, convergence, current_traversal, current_deps, updated_at) VALUES (%s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s, %s)
2015-08-28 08:20:27.775 23 INFO sqlalchemy.engine.base.Engine [req-70392def-f8ab-45cf-b4f9-b913d8a90933 admin admin] (datetime.datetime(2015, 8, 28, 8, 20, 27, 775090), None, 'CREATE', 'IN_PROGRESS', '', '9cf497c7-7878-4003-834b-5f9be9749716', 'test3', 5L, None, 'admin', 'cedcac1041224d0db4d77b223b16033c', u'3', None, None, None, 1, None, 0, 0, 0, None, 'null', None)
2015-08-28 08:20:27.776 23 INFO sqlalchemy.engine.base.Engine [req-70392def-f8ab-45cf-b4f9-b913d8a90933 admin admin] COMMIT

However.... (ignore the errored state, thats fine, the created_at field is the issue)

mysql> select * from stack where id='9cf497c7-7878-4003-834b-5f9be9749716' \G
*************************** 1. row ***************************
                   id: 9cf497c7-7878-4003-834b-5f9be9749716
           created_at: 2015-08-28 08:20:27.000000
           updated_at: NULL
           deleted_at: NULL
                 name: test3
     ...

[Steven Hardy (shardy)]

Interestingly, this migration appears to be skipped for me, running mariadb 10.0.21-1 on Fedora 21:

bash-4.3$ heat-manage db_sync
2015-08-28 11:07:11.948 INFO migrate.versioning.api [-] 62 -> 63...
2015-08-28 11:07:12.121 INFO migrate.versioning.api [-] done
2015-08-28 11:07:12.121 INFO migrate.versioning.api [-] 63 -> 64...
/usr/lib/python2.7/site-packages/pymysql/cursors.py:134: Warning: Table 'mysql.column_stats' doesn't exist
  result = self._query(query)
/usr/lib/python2.7/site-packages/pymysql/cursors.py:134: Warning: Table 'mysql.index_stats' doesn't exist
  result = self._query(query)
2015-08-28 11:07:12.257 INFO migrate.versioning.api [-] done
2015-08-28 11:07:12.258 INFO migrate.versioning.api [-] 64 -> 65...
2015-08-28 11:07:12.259 WARNING 065_update_at_fsp [-] Migration 065 could not be applied as the MySQl server version is below 5.6.4. Once the server has been upgraded this migration will need to be manually applied.
2015-08-28 11:07:12.275 INFO migrate.versioning.api [-] done
-bash-4.3$ heat-manage db_version
65

And, I don't see this issue, e.g delete's work fine for me.. I'm wondering how that version calculation is being done?

[Steven Hardy (shardy)]

Re comment #11 - derekh has encountered this issue in TripleO CI, and despite us both running the same mariadb version on F21, the migration is skipped for me, and not for him, resulting in datetime(6) which breaks us.

I think the quickest fix here is to revert the migration while we work out the dependency which is breaking things.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/218195

[Steven Hardy (shardy)]

MariaDB [heat]> SELECT @@version
    -> ;
+---------------------+
| @@version |
+---------------------+
| 10.0.21-MariaDB-log |
+---------------------+
1 row in set (0.01 sec)

It's not clear to me why my migration is skipped and it's not for others..

[Sam Yaple (s8m)]

Im glad im not going crazy here!

To asalkeld credit, it was early on suggested to revert this migration once I figured out the these particular field types were causing the issue.

Thanks for the decision to revert shary, I pdb stepped through all of sqlalchemy and couldn't figure out where the breakdown was. I was pulling my hair out.

Now you have to figure out what caused it :D

For additional information, I was using the MariaDB 10 with the wsrep patches for galera. The package was provided via a repo using the repotool on mariadb's site. https://downloads.mariadb.org/mariadb/repositories/

Perhaps try that package?

[Derek Higgins (derekh)]

Looks to me like the problem is in either MySQL-python or more low level

I can manually execute the select query, see results below the created_at column is being returned as expected

But when I trace into the code, the same query is missing the created_at value[2]

some relevant package versions[3]

[1] ==============================
MariaDB [heat]> SELECT software_config.created_at AS software_config_created_at, software_config.updated_at AS software_config_updated_at, software_config.id AS software_config_id, software_config.name AS software_config_name, software_config.`group` AS software_config_group, software_config.config AS software_config_config, software_config.tenant AS software_config_tenant \nFROM software_config \nWHERE software_config.id = '017a9c0e-33c7-4fb7-be88-2f64c8957a18';
PAGER set to stdout
PAGER set to stdout
+----------------------------+----------------------------+--------------------------------------+-------------------------------------------------+-----------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------+
| software_config_created_at | software_config_updated_at | software_config_id | software_config_name | software_config_group | software_config_config | software_config_tenant |
+----------------------------+----------------------------+--------------------------------------+-------------------------------------------------+-----------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------+
| 2015-08-28 11:02:17.000000 | NULL | 017a9c0e-33c7-4fb7-be88-2f64c8957a18 | overcloud2-ControllerClusterConfig-33ttfj6gxwtv | os-apply-config | {"inputs": [], "config": {"haproxy": {"nodes": [{"ip": "192.0.2.10", "name": "overcloud2-controller-0"}]}, "corosync": {"nodes": [{"ip": "192.0.2.10", "name": "overcloud2-controller-0"}]}, "horizon": {"caches": {"memcached": {"nodes": ["overcloud2-controller-0"]}}}, "mysql": {"nodes": [{"ip": "192.0.2.10", "name": "overcloud2-controller-0"}]}}, "options": {}, "outputs": []} | 4956709c955145cba82d133a98a7a473 |
+---...

[Derek Higgins (derekh)]

======================= Standalone script to display the problem
[root@localhost ~]# cat t.py
import MySQLdb, pdb

cnx = MySQLdb.connect(user='heat', passwd='unset', host='127.0.0.1', db='heat')
cursor = cnx.cursor()

query = 'SELECT created_at, name FROM software_config WHERE software_config.id = "017a9c0e-33c7-4fb7-be88-2f64c8957a18"'

#pdb.set_trace()
cursor.execute(query)
print cursor.fetchone()

[root@localhost ~]# python t.py
(None, 'overcloud2-ControllerClusterConfig-33ttfj6gxwtv')

Looks like the problem is client side, tcpdump verifies the correct date is being sent to the client

15:54:05.986925 IP 127.0.0.1.39285 > 127.0.0.1.3306: Flags [P.], seq 196:311, ack 126, win 342, options [nop,nop,TS val 29743004 ecr 29742260], length 115
...SELECT created_at, name FROM software_config WHERE software_config.id = "017a9c0e-33c7-4fb7-be88-2f64c8957a18"
15:54:05.987970 IP 127.0.0.1.3306 > 127.0.0.1.39285: Flags [P.], seq 126:376, ack 311, win 350, options [nop,nop,TS val 29743005 ecr 29743004], length 250
E....o@.@.,Q...........u9%.B.e.g...^.".....
.............L....def.heat.software_config.software_config
created_at
created_at.?...........@....def.heat.software_config.software_config.name.name......................K....2015-08-28 11:02:17.000000/overcloud2-ControllerClusterConfig-33ttfj6gxwtv.........
15:54:05.988025 IP 127.0.0.1.39285 > 127.0.0.1.3306: Flags [.], ack 376, win 350, options [nop,nop,TS val 29743005 ecr 29743005], length 0
E..4s.@.@............u...e.g9%.<...^.(.....
........

I believe the problem is in MySQLdb/MySQLdb/times.py

def DateTime_or_None(s):
    <snip/>
    try:
        d, t = s.split(sep, 1)
        return datetime(*[ int(x) for x in d.split('-')+t.split(':') ])
    except:
        return Date_or_None(s)

The is no allowance in this function for a "." in the datetime, so it returns None

This is what thrown and caught
ValueError: invalid literal for int() with base 10: '17.000000'

[Sam Yaple (s8m)]

While this is almost certainly the case, my question you be why does this break mariadb only? (and whats up with the migration applying sporadically)?

[Sam Yaple (s8m)]

Tested an working, though the database still stores the time with 000000 as the microseconds, so likely other parts of the code are affected.

        try:
            d, t = s.split(sep, 1)
            # Catch fractional seconds
            t = t.replace('.', ':')
            return datetime(*[ int(x) for x in d.split('-')+t.split(':') ])
        except:
            return Date_or_None(s)

[Sam Yaple (s8m)]

Looks like this was found, fixed, and commited two years ago. We are late to the party!

https://github.com/farcepest/MySQLdb1/commit/fb1c79d85a87345525ba82cfdca470c4ef565a3c

I am running version 1.2.3, that is tagged as fixed in 1.2.5

python-mysqldb:
  Installed: 1.2.3-2ubuntu1
  Candidate: 1.2.3-2ubuntu1
  Version table:
 *** 1.2.3-2ubuntu1 0
        500 http://us.archive.ubuntu.com/ubuntu/ trusty/main amd64 Packages
        100 /var/lib/dpkg/status

[Angus Salkeld (asalkeld)]

Great debugging everyone!

Note the schema is applied only to MySql as you have to "turn it on" with mysql, where as in other DB's it should just work. Also it is dependant on the mysql server version.

Have a look at the comments I added to the migration:
https://review.openstack.org/#/c/218195/1/heat/db/sqlalchemy/migrate_repo/versions/065_update_at_fsp.py

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/218195
Committed: https://git.openstack.org/cgit/openstack/heat/commit/?id=90abc6a2f0b3f6b98ef4ca862c8ece937901645b
Submitter: Jenkins
Branch: master

commit 90abc6a2f0b3f6b98ef4ca862c8ece937901645b
Author: Steven Hardy <email address hidden>
Date: Fri Aug 28 11:29:21 2015 +0100

    Revert "Make sure all "updated_at" fields store fractional seconds"

    This reverts commit 3b2d14ad993c1e605f0242f99eb2224bbc10c353.

    This has been causing heat to break for a number of users running
    mariadb 10 - this may be a dependency issue, but reverting this
    until we work out why things are broken seems the safest course
    of action.

    (Pulled from gate, can't pass until Neutron netaddr fix is landed in kilo) -- again

    Change-Id: If2b41f1c07803090ea7dd8591985a3f305404c2a
    Partial-Bug: #1488779

[Steve Baker (steve-stevebaker)]

For the purposes of l3 I'll mark this bug committed and reopen bug 1480739