/data/files_external/rootcerts.crt empty after update

[LukasReschke]

#3470 is back but this time it happens every time after an update via the web updater on c.nc.c.

[LukasReschke]

Looks really odd, the file cache claims the file hasn't been changed since 1475071065 which would be Wed, 28 Sep 2016 13:57:45 GMT 😱

mysql> select * from oc_filecache where name like "%rootcerts.crt%";
+--------+---------+------------------------------+----------------------------------+--------+---------------+----------+----------+--------+------------+---------------+-----------+------------------+----------------------------------+-------------+----------+
| fileid | storage | path                         | path_hash                        | parent | name          | mimetype | mimepart | size   | mtime      | storage_mtime | encrypted | unencrypted_size | etag                             | permissions | checksum |
+--------+---------+------------------------------+----------------------------------+--------+---------------+----------+----------+--------+------------+---------------+-----------+------------------+----------------------------------+-------------+----------+
|  25878 |      11 | files_external/rootcerts.crt | 96f0eb1b0b28e846975c98dbeb5e734d |  13459 | rootcerts.crt |        7 |        3 | 757353 | 1475071065 |    1475071065 |         0 |                0 | f91f134cfa8930a8a5755af742d03c64 |          27 |          |
+--------+---------+------------------------------+----------------------------------+--------+---------------+----------+----------+--------+------------+---------------+-----------+------------------+----------------------------------+-------------+----------+
1 row in set (2.95 sec)

mysql> select * from oc_filecache where fileid=13459;
+--------+---------+----------------+----------------------------------+--------+----------------+----------+----------+--------+------------+---------------+-----------+------------------+---------------+-------------+----------+
| fileid | storage | path           | path_hash                        | parent | name           | mimetype | mimepart | size   | mtime      | storage_mtime | encrypted | unencrypted_size | etag          | permissions | checksum |
+--------+---------+----------------+----------------------------------+--------+----------------+----------+----------+--------+------------+---------------+-----------+------------------+---------------+-------------+----------+
|  13459 |      11 | files_external | c270928b685e7946199afdfb898d27ea |    559 | files_external |        2 |        1 | 757353 | 1476779314 |    1471530083 |         0 |                0 | 5805dd33468f2 |          31 |          |
+--------+---------+----------------+----------------------------------+--------+----------------+----------+----------+--------+------------+---------------+-----------+------------------+---------------+-------------+----------+
1 row in set (0.00 sec)

mysql> select * from oc_filecache where fileid=559;
+--------+---------+------+----------------------------------+--------+------+----------+----------+-------------+------------+---------------+-----------+------------------+---------------+-------------+----------+
| fileid | storage | path | path_hash                        | parent | name | mimetype | mimepart | size        | mtime      | storage_mtime | encrypted | unencrypted_size | etag          | permissions | checksum |
+--------+---------+------+----------------------------------+--------+------+----------+----------+-------------+------------+---------------+-----------+------------------+---------------+-------------+----------+
|    559 |      11 |      | d41d8cd98f00b204e9800998ecf8427e |     -1 |      |        2 |        1 | 12605497564 | 1495225919 |    1493931405 |         0 |                0 | 591f563fdd015 |          23 |          |
+--------+---------+------+----------------------------------+--------+------+----------+----------+-------------+------------+---------------+-----------+------------------+---------------+-------------+----------+
1 row in set (0.00 sec)

[LukasReschke]

The following error log is also appearing around those times:

{"reqId":"H0v9Bq3mBEShyjFr1N71","level":3,"time":"2017-05-19T20:12:48+00:00","remoteAddr":"","user":"--","app":"PHP","method":"--","url":"--","message":"filemtime(): stat failed for /var/www/html/resources/config/ca-bundle.crt at /var/www/html/lib/private/Security/CertificateManager.php#275","userAgent":"--","version":"12.0.0.23"}

[LukasReschke]

Looking at the server logs when those cases happened I think I see the following similarities on update:

1. Cron seems to have run around that time
2. There are federated shares on this instance
3. The following log messages are in the server log and seem to be from cron:

{"reqId":"R0CpsfO22v1iKNCZWWDd","level":3,"time":"2017-05-21T21:00:43+00:00","remoteAddr":"","user":"--","app":"PHP","method":"--","url":"--","message":"include(\/var\/www\/html\/3rdparty\/composer\/..\/icewind\/streams\/src\/CallbackWrapper.php): failed to open stream: No such file or directory at \/var\/www\/html\/lib\/composer\/composer\/ClassLoader.php#444","userAgent":"--","version":"12.0.0.27"}
{"reqId":"R0CpsfO22v1iKNCZWWDd","level":3,"time":"2017-05-21T21:00:43+00:00","remoteAddr":"","user":"--","app":"PHP","method":"--","url":"--","message":"include(): Failed opening '\/var\/www\/html\/3rdparty\/composer\/..\/icewind\/streams\/src\/CallbackWrapper.php' for inclusion (include_path='\/var\/www\/html\/apps\/mail\/vendor\/pear-pear.horde.org\/Horde_Util:\/var\/www\/html\/apps\/mail\/vendor\/pear-pear.horde.org\/Horde_Exception:\/var\/www\/html\/apps\/mail\/vendor\/pear-pear.horde.org\/Horde_Stream_Filter:\/var\/www\/html\/apps\/mail\/vendor\/pear-pear.horde.org\/Horde_Stream:\/var\/www\/html\/apps\/mail\/vendor\/pear-pear.horde.org\/Horde_Socket_Client:\/var\/www\/html\/apps\/mail\/vendor\/pear-pear.horde.org\/Horde_Stream_Wrapper:\/var\/www\/html\/apps\/mail\/vendor\/pear-pear.horde.org\/Horde_Secret:\/var\/www\/html\/apps\/mail\/vendor\/pear-pear.horde.org\/Horde_Text_Flowed:\/var\/www\/html\/apps\/mail\/vendor\/pear-pear.horde.org\/Horde_Mail:\/var\/www\/html\/apps\/mail\/vendor\/pear-pear.horde.org\/Horde_ListHeaders:\/var\/www\/html\/apps\/mail\/vendor\/pear-pear.horde.org\/Horde_Translation:\/var\/www\/html\/apps\/mail\/vendor\/pear-pear.horde.org\/Horde_Support:\/var\/www\/html\/apps\/mail\/vendor\/pear-pear.horde.org\/Horde_Crypt_Blowfish:\/var\/www\/html\/apps\/mail\/vendor\/pear-pear.horde.org\/Horde_Nls:\/var\/www\/html\/apps\/mail\/vendor\/pear-pear.horde.org\/Horde_Date:\/var\/www\/html\/apps\/mail\/vendor\/pear-pear.horde.org\/Horde_Mime:\/var\/www\/html\/apps\/mail\/vendor\/pear-pear.horde.org\/Horde_Idna:\/var\/www\/html\/apps\/mail\/vendor\/pear-pear.horde.org\/Horde_Imap_Client:\/var\/www\/html\/apps\/mail\/vendor\/pear-pear.horde.org\/Horde_Smtp:\/var\/www\/html\/apps\/mail\/vendor\/pear-pear.horde.org\/Horde_Text_Filter:\/var\/www\/html\/3rdparty\/pear\/console_getopt:\/var\/www\/html\/3rdparty\/pear\/pear_exception:\/var\/www\/html\/3rdparty\/pear\/archive_tar:\/var\/www\/html\/3rdparty\/pear\/pear-core-minimal\/src:\/var\/www\/html\/apps') at \/var\/www\/html\/lib\/composer\/composer\/ClassLoader.php#444","userAgent":"--","version":"12.0.0.27"}
{"reqId":"R0CpsfO22v1iKNCZWWDd","level":4,"time":"2017-05-21T21:00:44+00:00","remoteAddr":"","user":"--","app":"cron","method":"--","url":"--","message":"Class 'Icewind\\Streams\\CallbackWrapper' not found","userAgent":"--","version":"12.0.0.27"}

Let's see if that helps to reproduce this situation somehow.

[blizzz]

cron is not supposed to be running in maintenance mode. Or does it? 🙈

[ChristophWurst]

cron is not supposed to be running in maintenance mode. Or does it? 🙈

Also what if we check for maintenance mode, see it's disabled and run cron? Then an update is performed while cron is still running (because it does time consuming tasks). Maybe we should check whether it's running, if that's possible at all.

[blizzz]

IIRC it creates a lock file in the data dir. It already detects the state itself to prevent running in parallel if the last run did not finish.

[MorrisJobke]

It creates a DB entry - parallel runs are supported and will double the speed to process a tasks ;)

[blizzz]

doh … 👴 … thanks for dating me up @MorrisJobke

[MorrisJobke]

doh … 👴 … thanks for dating me up @MorrisJobke

Afaik there since 10 or 11. I guess @nickvergessen worked on this 😉

[LukasReschke]

Happened again after update:

root@cloud:/var/www/data/files_external# ls -lah
total 8.0K
drwxr-xr-x  2 www-data www-data 4.0K Jul 12 14:06 .
drwxrwx--- 34 www-data www-data 4.0K Jun 28 19:25 ..
-rw-r--r--  1 www-data www-data    0 Jul 18 08:08 rootcerts.crt

[LukasReschke]

I updated via PHAR this time.

[nickvergessen]

Some ideas:

• Create a non-changable cert file that is used as a fallback when the other one is empty
• When writing the cert file always write to a new name and change a config when the file is none empty which keeps the current name

[MorrisJobke]

Should be fixed by #9562

[MorrisJobke]

Potential fix is in #9900

[MorrisJobke]

Let's see if this happens again on an upgrade to 14+. For now I will close it.