Bug 1304460 - cinder services writing to deleted log files / SIGHUP issues
cinder services writing to deleted log files / SIGHUP issues
Status: CLOSED DUPLICATE of bug 1309387
Product: Red Hat OpenStack
Classification: Red Hat
Component: openstack-cinder (Show other bugs)
8.0 (Liberty)
Unspecified Unspecified
unspecified Severity high
: ga
: 8.0 (Liberty)
Assigned To: Eric Harney
nlevinki
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2016-02-03 11:46 EST by Eric Harney
Modified: 2016-04-26 22:44 EDT (History)
4 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2016-02-21 02:14:24 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Eric Harney 2016-02-03 11:46:59 EST
Description of problem:
On my OSP8 install, cinder-api and cinder-volume are writing to deleted log files.  I suspect this is related to log rotation.

Nova, ceilometer, keystone, and neutron do not appear to be doing this despite having logs rotated.

Version-Release number of selected component (if applicable):
python-cinder-7.0.1-5.el7ost.noarch
openstack-cinder-7.0.1-5.el7ost.noarch

How reproducible:
Spotted on my environment once so far.  (10.16.151.137)

Steps to Reproduce:
1.  Install Cinder w/ packstack
2.  Leave running for more than a week
3.  Look for logs

Additional info:
# service openstack-cinder-api status
Redirecting to /bin/systemctl status  openstack-cinder-api.service
● openstack-cinder-api.service - OpenStack Cinder API Server
   Loaded: loaded (/usr/lib/systemd/system/openstack-cinder-api.service; enabled; vendor preset: disabled)
   Active: active (running) since Fri 2016-01-22 15:28:21 EST; 1 weeks 4 days ago
 Main PID: 9722 (cinder-api)
   CGroup: /system.slice/openstack-cinder-api.service
           ├─9722 /usr/bin/python2 /usr/bin/cinder-api --config-file /usr/share/cinder/cinder-dist.conf --config-file /etc/cinder/cinder.conf --logfile /var/log/cinder/ap...
           ├─9733 /usr/bin/python2 /usr/bin/cinder-api --config-file /usr/share/cinder/cinder-dist.conf --config-file /etc/cinder/cinder.conf --logfile /var/log/cinder/ap...
           ├─9734 /usr/bin/python2 /usr/bin/cinder-api --config-file /usr/share/cinder/cinder-dist.conf --config-file /etc/cinder/cinder.conf --logfile /var/log/cinder/ap...
           ├─9735 /usr/bin/python2 /usr/bin/cinder-api --config-file /usr/share/cinder/cinder-dist.conf --config-file /etc/cinder/cinder.conf --logfile /var/log/cinder/ap...
           └─9736 /usr/bin/python2 /usr/bin/cinder-api --config-file /usr/share/cinder/cinder-dist.conf --config-file /etc/cinder/cinder.conf --logfile /var/log/cinder/ap...

Warning: Journal has been rotated since unit was started. Log output is incomplete or unavailable.
[root@dhcp148-231 cinder]# rpm -qi openstack-cinder python-cinder
Name        : openstack-cinder
Epoch       : 1
Version     : 7.0.1
Release     : 5.el7ost
Architecture: noarch
Install Date: Fri 22 Jan 2016 11:45:10 AM EST
Group       : Unspecified
Size        : 141495
License     : ASL 2.0
Signature   : RSA/SHA256, Tue 19 Jan 2016 02:57:58 PM EST, Key ID 938a80caf21541eb
Source RPM  : openstack-cinder-7.0.1-5.el7ost.src.rpm
Build Date  : Thu 14 Jan 2016 03:58:26 AM EST
Build Host  : x86-036.build.eng.bos.redhat.com
Relocations : (not relocatable)
Packager    : Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>
Vendor      : Red Hat, Inc.
URL         : http://www.openstack.org/software/openstack-storage/
Summary     : OpenStack Volume service
Description :
OpenStack Volume (codename Cinder) provides services to manage and
access block storage volumes for use by Virtual Machine instances.
Name        : python-cinder
Epoch       : 1
Version     : 7.0.1
Release     : 5.el7ost
Architecture: noarch
Install Date: Fri 22 Jan 2016 11:45:09 AM EST
Group       : Applications/System
Size        : 12824530
License     : ASL 2.0
Signature   : RSA/SHA256, Tue 19 Jan 2016 02:58:21 PM EST, Key ID 938a80caf21541eb
Source RPM  : openstack-cinder-7.0.1-5.el7ost.src.rpm
Build Date  : Thu 14 Jan 2016 03:58:26 AM EST
Build Host  : x86-036.build.eng.bos.redhat.com
Relocations : (not relocatable)
Packager    : Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>
Vendor      : Red Hat, Inc.
URL         : http://www.openstack.org/software/openstack-storage/
Summary     : OpenStack Volume Python libraries
Description :
OpenStack Volume (codename Cinder) provides services to manage and
access block storage volumes for use by Virtual Machine instances.


[root@dhcp148-231 cinder]# lsof -p 9722 | grep log
cinder-ap 9722 cinder  mem       REG              253,1     11600 34004880 /usr/lib64/python2.7/lib-dynload/syslog.so
cinder-ap 9722 cinder    3w      REG              253,1   1044434  1129185 /var/log/cinder/api.log-20160124 (deleted)

[root@dhcp148-231 cinder]# ls -l /var/log/cinder/api*
-rw-r--r--. 1 cinder cinder     0 Jan 24 03:17 /var/log/cinder/api.log
-rw-r--r--. 1 cinder cinder 73104 Jan  8 17:29 /var/log/cinder/api.log-20160110.gz
-rw-r--r--. 1 cinder cinder 44116 Jan 21 11:46 /var/log/cinder/api.log-20160122.gz
-rw-r--r--. 1 cinder cinder 88684 Jan 22 15:35 /var/log/cinder/api.log-20160124.gz

[root@dhcp148-231 cinder]# cat /etc/logrotate.d/openstack-cinder 
compress

/var/log/cinder/*.log {
    weekly
    rotate 4
    missingok
    compress
    minsize 100k
}
Comment 2 Eric Harney 2016-02-03 12:23:17 EST
Note: I manually sent a SIGHUP to cinder-volume and it then opened a new log file.

Possible cinder bug where SIGHUP is sometimes ignored/ineffective?
Comment 3 Eric Harney 2016-02-03 12:28:31 EST
... which resulted in a worse problem.

An LVM volume wipe was running, dd'ing the device.

The SIGHUP reloaded the volume driver, which started the delete again, causing a second dd process to start to the same device.


2016-02-03 12:23:32.638 7467 INFO oslo_service.service [req-dcb674ab-972a-40f0-a9c5-eaa0e176833d - - - - -] Caught SIGHUP, stopping children
2016-02-03 12:23:32.643 7467 WARNING oslo_config.cfg [req-dcb674ab-972a-40f0-a9c5-eaa0e176833d - - - - -] Option "logdir" from group "DEFAULT" is deprecated. Use option "log-dir" from group "DEFAULT".
2016-02-03 12:23:32.653 7549 INFO oslo_service.service [req-dcb674ab-972a-40f0-a9c5-eaa0e176833d - - - - -] Child caught SIGHUP, exiting
2016-02-03 12:23:32.662 7549 WARNING oslo_config.cfg [req-dcb674ab-972a-40f0-a9c5-eaa0e176833d - - - - -] Option "logdir" from group "DEFAULT" is deprecated. Use option "log-dir" from group "DEFAULT".
2016-02-03 12:23:32.673 7549 INFO cinder.service [-] Starting cinder-volume node (version 7.0.1)
2016-02-03 12:23:32.674 7549 INFO cinder.volume.manager [req-3130f73d-f6fd-4d82-9fad-85891ec61b49 - - - - -] Starting volume driver LVMVolumeDriver (3.0.0)
2016-02-03 12:23:33.186 7549 WARNING oslo_config.cfg [req-3130f73d-f6fd-4d82-9fad-85891ec61b49 - - - - -] Option "lock_path" from group "DEFAULT" is deprecated. Use option "lock_path" from group "oslo_concurrency".
2016-02-03 12:23:33.369 7549 INFO cinder.volume.targets.iscsi [req-3130f73d-f6fd-4d82-9fad-85891ec61b49 - - - - -] Skipping remove_export. No iscsi_target is presently exported for volume: fb38e727-9ebc-4d7f-ac33-f398c3b67fd7
2016-02-03 12:23:33.626 7549 INFO cinder.volume.utils [req-3130f73d-f6fd-4d82-9fad-85891ec61b49 - - - - -] Performing secure delete on volume: /dev/mapper/cinder--volumes-volume--fb38e727--9ebc--4d7f--ac33--f398c3b67fd7



7467 ?        Ss   164:57 /usr/bin/python2 /usr/bin/cinder-volume --config-file /usr/share/cinder/cinder-dist.conf --config-file /etc/cinder/cinder.conf --logfile /var/log/
 7549 ?        S      0:03  \_ /usr/bin/python2 /usr/bin/cinder-volume --config-file /usr/share/cinder/cinder-dist.conf --config-file /etc/cinder/cinder.conf --logfile /var/
 7676 ?        S      0:00      \_ sudo cinder-rootwrap /etc/cinder/rootwrap.conf cgexec -g blkio:cinder-volume-copy dd if=/dev/zero of=/dev/mapper/cinder--volumes-volume--f
 7677 ?        S      0:00      |   \_ /usr/bin/python2 /usr/bin/cinder-rootwrap /etc/cinder/rootwrap.conf cgexec -g blkio:cinder-volume-copy dd if=/dev/zero of=/dev/mapper/
 7678 ?        D      0:00      |       \_ dd if=/dev/zero of=/dev/mapper/cinder--volumes-volume--fb38e727--9ebc--4d7f--ac33--f398c3b67fd7 count=1 bs=1M oflag=direct
19218 ?        S      0:00      \_ sudo cinder-rootwrap /etc/cinder/rootwrap.conf cgexec -g blkio:cinder-volume-copy dd if=/dev/zero of=/dev/mapper/cinder--volumes-volume--f
19219 ?        S      0:00          \_ /usr/bin/python2 /usr/bin/cinder-rootwrap /etc/cinder/rootwrap.conf cgexec -g blkio:cinder-volume-copy dd if=/dev/zero of=/dev/mapper/
19220 ?        D      0:00              \_ dd if=/dev/zero of=/dev/mapper/cinder--volumes-volume--fb38e727--9ebc--4d7f--ac33--f398c3b67fd7 count=1 bs=1M oflag=direct
Comment 4 Sergey Gotliv 2016-02-07 14:53:52 EST
Log issue is probably fixed by https://review.openstack.org/#/c/208366/.

This upstream launchpad https://bugs.launchpad.net/oslo-incubator/+bug/1276694 is related to the SIGHUP issue described here.
Comment 5 Eric Harney 2016-02-08 10:28:26 EST
It may be cleanest to fix the log issue by configuring logrotate to use the "copytruncate" method.
Comment 6 Sergey Gotliv 2016-02-17 05:51:05 EST
(In reply to Eric Harney from comment #5)
> It may be cleanest to fix the log issue by configuring logrotate to use the
> "copytruncate" method.

Agree. Btw, that approach is already proposed in BZ#1299899
Comment 7 Sergey Gotliv 2016-02-21 02:14:24 EST

*** This bug has been marked as a duplicate of bug 1309387 ***

Note You need to log in before you can comment on or make changes to this bug.