Deployment log is broken

[Serg Melikyan]

Steps to Reproduce
1. Deploy Apache application

Expected results:
1. Open Environment -> Last Deployment Log
2. Log Contains:
Deployment scheduled
Creating VM for Apache Server.
Instance is created. Deploying Apache
Apache is installed.
Apache is available at ...
Deployment finished

Actual Result
1. Open Environment -> Last Deployment Log
2. Log Contains:
Deployment scheduled
Deployment finished

Additional information:

murano-engine.log contains following exception:

2016-04-15 00:16:45.528 909 DEBUG murano.common.server [-] Got report from orchestration engine:
{u'environment_id': u'199e907a12984d3b80bd68f6d7405dc9', u'level': u'info', u'text': u'Creating VM for Apache Server.', u'details': None, u'timestamp': u'2016-04-15T00:16:45Z', u'id': u'e93b3ca7-48e5-4c6c-92d0-2c32489479a5'} report_notification /usr/lib/python2.7/dist-packages/murano/common/server.py:175
2016-04-15 00:16:45.564 909 ERROR oslo_messaging.notify.dispatcher [-] Exception during message handling
2016-04-15 00:16:45.564 909 ERROR oslo_messaging.notify.dispatcher Traceback (most recent call last):
016-04-15 00:16:45.564 909 ERROR oslo_messaging.notify.dispatcher DBDataError: (_mysql_exceptions.OperationalError) (1292, "Incorrect datetime value: '2016-04-15 00:16:45+00:00' for column 'created' at row 1") [SQL: u'INSERT INTO status (created, updated, id, entity_id, entity, task_id, text, level, details) VALUES (%s, %s, %s, %s, %s, %s, %s, %s, %s)'] [parameters: (datetime.datetime(2016, 4, 15, 0, 16, 45, tzinfo=<iso8601.iso8601.Utc object at 0x7fcf5e567550>), datetime.datetime(2016, 4, 15, 0, 16, 45, 550656), '17e2d9415e844ecf820fc27bb3bd8b4a', 'e93b3ca7-48e5-4c6c-92d0-2c32489479a5', None, '82a12c20c76e47bb89930db9d6bf9051', 'Creating VM for Apache Server.', 'info', None)]

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/mitaka
Review: https://review.openstack.org/310142

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/307391
Committed: https://git.openstack.org/cgit/openstack/murano/commit/?id=a787d631ec0b0132c9504eca0a71aaef3cb445da
Submitter: Jenkins
Branch: master

commit a787d631ec0b0132c9504eca0a71aaef3cb445da
Author: Stan Lagun <email address hidden>
Date: Mon Apr 18 10:49:35 2016 -0700

    Deployment reports datetime DB insertion was fixed

    When MySQL is used as a database backend deployment
    notification reports could not be persisted due to the
    fact that MySQL could not store timezone offset of
    datetime.datetime.

    Change-Id: Iea3b7d8d37ac68f0ebdcdcf96471a0d18a29469f
    Closes-Bug: #1570933

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/310142
Committed: https://git.openstack.org/cgit/openstack/murano/commit/?id=9c6df8154f3257967dc179441ecfde13e36be6ad
Submitter: Jenkins
Branch: stable/mitaka

commit 9c6df8154f3257967dc179441ecfde13e36be6ad
Author: Stan Lagun <email address hidden>
Date: Mon Apr 18 10:49:35 2016 -0700

    Deployment reports datetime DB insertion was fixed

    When MySQL is used as a database backend deployment
    notification reports could not be persisted due to the
    fact that MySQL could not store timezone offset of
    datetime.datetime.

    Change-Id: Iea3b7d8d37ac68f0ebdcdcf96471a0d18a29469f
    Closes-Bug: #1570933
    (cherry picked from commit a787d631ec0b0132c9504eca0a71aaef3cb445da)

[magicboiz (magicboiz)]

Hi, this might be incorrect from my side, but I think I'm also facinf this bug.

MOS 8.0 over ubuntu 14.04. After MANTAINANCE UPDATE 1 (https://docs.mirantis.com/openstack/fuel/fuel-8.0/maintenance-updates.html#mu8-0-how-to-update), I'm getting the same error:

2016-05-21 19:59:29.234 2870 ERROR oslo_messaging.notify.dispatcher
<131>May 21 19:59:30 node-5 murano-api: 2016-05-21 19:59:30.599 2870 ERROR oslo_messaging.notify.dispatcher [-] Exception during message handling
2016-05-21 19:59:30.599 2870 ERROR oslo_messaging.notify.dispatcher Traceback (most recent call last):
2016-05-21 19:59:30.599 2870 ERROR oslo_messaging.notify.dispatcher File "/usr/lib/python2.7/dist-packages/oslo_messaging/notify/dispatcher.py", line 92, in _dispatch_and_handle_error
2016-05-21 19:59:30.599 2870 ERROR oslo_messaging.notify.dispatcher executor_callback)
2016-05-21 19:59:30.599 2870 ERROR oslo_messaging.notify.dispatcher File "/usr/lib/python2.7/dist-packages/oslo_messaging/notify/dispatcher.py", line 135, in _dispatch
2016-05-21 19:59:30.599 2870 ERROR oslo_messaging.notify.dispatcher metadata)
2016-05-21 19:59:30.599 2870 ERROR oslo_messaging.notify.dispatcher File "/usr/lib/python2.7/dist-packages/murano/common/server.py", line 140, in _handler
2016-05-21 19:59:30.599 2870 ERROR oslo_messaging.notify.dispatcher func(payload)
2016-05-21 19:59:30.599 2870 ERROR oslo_messaging.notify.dispatcher File "/usr/lib/python2.7/dist-packages/murano/common/server.py", line 193, in report_notification
2016-05-21 19:59:30.599 2870 ERROR oslo_messaging.notify.dispatcher unit.add(status)
2016-05-21 19:59:30.599 2870 ERROR oslo_messaging.notify.dispatcher File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 490, in __exit__
2016-05-21 19:59:30.599 2870 ERROR oslo_messaging.notify.dispatcher self.rollback()
2016-05-21 19:59:30.599 2870 ERROR oslo_messaging.notify.dispatcher File "/usr/lib/python2.7/dist-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
2016-05-21 19:59:30.599 2870 ERROR oslo_messaging.notify.dispatcher compat.reraise(exc_type, exc_value, exc_tb)
2016-05-21 19:59:30.599 2870 ERROR oslo_messaging.notify.dispatcher File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 487, in __exit__
2016-05-21 19:59:30.599 2870 ERROR oslo_messaging.notify.dispatcher self.commit()
2016-05-21 19:59:30.599 2870 ERROR oslo_messaging.notify.dispatcher File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 392, in commit
2016-05-21 19:59:30.599 2870 ERROR oslo_messaging.notify.dispatcher self._prepare_impl()
2016-05-21 19:59:30.599 2870 ERROR oslo_messaging.notify.dispatcher File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 372, in _prepare_impl
2016-05-21 19:59:30.599 2870 ERROR oslo_messaging.notify.dispatcher self.session.flush()
2016-05-21 19:59:30.599 2870 ERROR oslo_messaging.notify.dispatcher File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 2004, in flush
2016-05-21 19:59:30.599 2870 ERROR oslo_messaging.notify.dispatcher self._flush(objects)
2016-05-21 19:59:30.599 2870 ERROR oslo_messaging.notify.dispat...

[Serg Melikyan (smelikyan)]

magicboiz (magicboiz), you can track status of this bug in Mirantis OpenStack by the following link: https://bugs.launchpad.net/mos/+bug/1570932

I've nominated this bug for the next 8.0 MU

[Doug Hellmann (doug-hellmann)]

This issue was fixed in the openstack/murano 3.0.0.0b1 development milestone.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/liberty
Review: https://review.openstack.org/325941

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/325941
Committed: https://git.openstack.org/cgit/openstack/murano/commit/?id=12ed525c1b151ca01dc90a93857a921a2e733c75
Submitter: Jenkins
Branch: stable/liberty

commit 12ed525c1b151ca01dc90a93857a921a2e733c75
Author: Stan Lagun <email address hidden>
Date: Mon Apr 18 10:49:35 2016 -0700

    Deployment reports datetime DB insertion was fixed

    When MySQL is used as a database backend deployment
    notification reports could not be persisted due to the
    fact that MySQL could not store timezone offset of
    datetime.datetime.

    Change-Id: Iea3b7d8d37ac68f0ebdcdcf96471a0d18a29469f
    Closes-Bug: #1570933
    (cherry picked from commit a787d631ec0b0132c9504eca0a71aaef3cb445da)

[Doug Hellmann (doug-hellmann)]

This issue was fixed in the openstack/murano 2.0.1 release.

[Doug Hellmann (doug-hellmann)]

This issue was fixed in the openstack/murano 1.0.3 release.

[Tena Pavlovic (terezija-cosic)]

Hi, I also have very similar log when trying to deploy environment with MySQL, with imported SqlDatabase Library and Debian 8 x64 (pre-installed murano-agent) on Liberty/murano-api 1.0.2. So my problem is not broken log, but failed deployment of MySQL environment. Time on controller is OK and mysql> select curtime() shows correct time, but incorrect datetime error (1292) shows 2 hours less. Log is in attachment.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/murano 1.0.3 release.