fast growing logfile due to "file not found" errors #27567

umlaeute · 2017-04-05T08:40:58Z

i'm using owncloud-9.0.8-1.1 (Debian package as provided one owncloud.org).

our instance has become a bit sluggish, so i investigated a bit and the first thing i noticed that the owncloud.log file has grown to a considerable size of ~15GB, but this was during the last 6 months (and it seems i forgot to configure logfile rotation).

so i manually rotated the logfile, only to discover that it seems to be growning increasingly fast:
in less than 24h, the logfile has grown by ~720MB(!).

quick logfile analysis

a quick glance at the logfile (the "small" 700MB file, not the unwieldly 15GB one) did not reveal anything very special (though my eyes still hurt due to excessive backslash spread).

most errors (about 70%, or 275000 lines) are about "File with id ... has not been found":

{"reqId":"TK5kxqzynJjC71GC6S5w","remoteAddr":"192.168.0.172","app":"no app in context","message":"Exception: {\"Exception\":\"OCP\\\\Files\\\\NotFoundException\",\"Message\":\"File with id \\\"470793\\\" has not been found.\",\"Code\":0,\"Trace\":\"#0 \\\/var\\\/www\\\/owncloud\\\/apps\\\/files_sharing\\\/lib\\\/sharedstorage.php(90): OC\\\\Files\\\\View->getPath(470793, false)\\n#1 \\\/var\\\/www\\\/owncloud\\\/apps\\\/files_sharing\\\/lib\\\/sharedstorage.php(581): OC\\\\Files\\\\Storage\\\\Shared->init()\\n#2 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/storage\\\/wrapper\\\/wrapper.php(381): OC\\\\Files\\\\Storage\\\\Shared->getCache('', Object(OCA\\\\Files_Trashbin\\\\Storage))\\n#3 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/view.php(1343): OC\\\\Files\\\\Storage\\\\Wrapper\\\\Wrapper->getCache('')\\n#4 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/node\\\/root.php(179): OC\\\\Files\\\\View->getFileInfo('\\\/20160cc4-10e9-...')\\n#5 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/node\\\/root.php(341): OC\\\\Files\\\\Node\\\\Root->get('\\\/20160cc4-10e9-...')\\n#6 \\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/server.php(746): OC\\\\Files\\\\Node\\\\Root->getUserFolder('20160cc4-10e9-1...')\\n#7 \\\/var\\\/www\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/connector\\\/sabre\\\/serverfactory.php(125): OC\\\\Server->getUserFolder()\\n#8 [internal function]: OCA\\\\DAV\\\\Connector\\\\Sabre\\\\ServerFactory->OCA\\\\DAV\\\\Connector\\\\Sabre\\\\{closure}(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#9 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Object(Closure), Array)\\n#10 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(446): Sabre\\\\Event\\\\EventEmitter->emit('beforeMethod', Array)\\n#11 \\\/var\\\/www\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(248): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#12 \\\/var\\\/www\\\/owncloud\\\/apps\\\/dav\\\/appinfo\\\/v1\\\/webdav.php(56): Sabre\\\\DAV\\\\Server->exec()\\n#13 \\\/var\\\/www\\\/owncloud\\\/remote.php(138): require_once('\\\/var\\\/www\\\/ownclo...')\\n#14 {main}\",\"File\":\"\\\/var\\\/www\\\/owncloud\\\/lib\\\/private\\\/files\\\/view.php\",\"Line\":1686}","level":3,"time":"2017-04-05T08:07:27+00:00","method":"PROPFIND","url":"\/remote.php\/webdav\/","user":"20160cc4-10e9-1031-8ba5-69a70758f5ca"}

of these errors about 89% (245000 lines) come from only two users (and their /files/ are about 5.2GB resp 8.8GB in size).

cron

i'v read #25787, which suggests that the problem is either specific to 9.1 (which i don't use), or should go away automatically via the cron-scripts.

i'm using AJAX as the cron-backend, but i'm not sure whether it actually works.
the admin page tells me that cron has last executed just now and accessing /owncloud/cron.php yields a

 {"status":"success"}

which all sounds promising enough.
otoh, i tried to enable logrotation with a file-limit of 10 MB, and this doesn't seem to work at all (given that the current file is 720MB large):

$ occ log:owncloud
Log backend ownCloud: enabled
Log file: /var/www/owncloud/data/owncloud.log
Rotate at: 10 MB
$ ls -lha owncloud.log
-rw-r----- 1 www-data www-data 718M Apr  5 10:38 owncloud.log
$

Server configuration

Operating system: Debian GNU/Linux 8.7 (jessie)

Web server: apache2 (2.4.10-10+deb8u8)

Database: PostgreSQL9.4 (9.4.10-0+deb8u1)

PHP version: php5 (5.6.30+dfsg-0+deb8u1)

ownCloud version: 9.0.8 (stable)

Updated from an older ownCloud or fresh install: updated (about 8 months ago we migrated from owcloud-7 to owncloud-9.0.4; since then we have gradually updated to 9.0.8)

Where did you install ownCloud from:
via apt from http://download.owncloud.org/download/repositories/9.0/Debian_8.0/

Signing status (ownCloud 9.0 and above):

No errors have been found.

List of activated apps:

Enabled:
  - activity: 2.2.1
  - comments: 0.2
  - configreport: 0.1.1
  - dav: 0.1.6
  - documents: 0.12.1
  - federatedfilesharing: 0.1.0
  - federation: 0.0.4
  - files: 1.4.4
  - files_pdfviewer: 0.8.1
  - files_sharing: 0.9.1
  - files_texteditor: 2.1
  - files_trashbin: 0.8.0
  - files_versions: 1.2.0
  - files_videoplayer: 0.9.8
  - firstrunwizard: 1.1
  - gallery: 14.5.0
  - notifications: 0.2.3
  - provisioning_api: 0.4.1
  - systemtags: 0.2
  - templateeditor: 0.1
  - updatenotification: 0.1.0
  - user_ldap: 0.8.0
Disabled:
  - encryption
  - external
  - files_antivirus
  - files_external
  - user_external

The content of config/config.php:

{
    "system": {
        "instanceid": "ocb6155c0dd2",
        "version": "9.0.8.2",
        "installed": true,
        "maintenance": false,
        "singleuser": false,
        "updatechecker": false,
        "name": "fooCloud",
        "title": "fooCloud",
        "theme": "foo",
        "trusted_domains": [
            "cloud.foo.at",
            "cloud.foonet"
        ],
        "loglevel": 3,
        "datadirectory": "\/var\/www\/owncloud\/data",
        "trashbin_retention_obligation": "auto",
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "dbtype": "pgsql",
        "dbhost": "localhost",
        "dbname": "owncloud",
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "dbtableprefix": "oc_",
        "lost_password_link": "https:\/\/users.foo.at\/login",
        "mail_domain": "foo.at",
        "mail_from_address": "noc",
        "mail_smtpdebug": false,
        "mail_smtpmode": "smtp",
        "mail_smtphost": "mail.foonet",
        "mail_smtpport": "25",
        "appstoreenabled": true,
        "appstore.experimental.enabled": false,
        "appstoreurl": "https:\/\/api.owncloud.com\/v1",
        "apps_paths": [
            {
                "path": "\/var\/www\/owncloud\/apps",
                "url": "\/apps",
                "writable": true
            }
        ],
        "enable_previews": true,
        "preview_libreoffice_path": "\/usr\/bin\/libreoffice",
        "preview_office_cl_parameters": " --headless --nologo --nofirststartwizard --invisible --norestore -convert-to pdf -outdir ",
        "ldapIgnoreNamingRules": false,
        "forcessl": true,
        "log_rotate_size": 10485760
    }

Are you using external storage, if yes which one: local/smb/sftp/...

no, but the local storage is mounted via NFS from a fileserver.

Are you using encryption: no

Are you using an external user-backend, if yes which one: LDAP

LDAP configuration (delete this part if not used)

+-------------------------------+---------------------------------------------+
| Configuration                 | s02                                         |
+-------------------------------+---------------------------------------------+
| hasMemberOfFilterSupport      |                                             |
| hasPagedResultSupport         |                                             |
| homeFolderNamingRule          |                                             |
| lastJpegPhotoLookup           | 0                                           |
| ldapAgentName                 |                                             |
| ldapAgentPassword             | ***                                         |
| ldapAttributesForGroupSearch  |                                             |
| ldapAttributesForUserSearch   | cn;uid;gecos                                |
| ldapBackupHost                |                                             |
| ldapBackupPort                |                                             |
| ldapBase                      | o=Staff,o=bar,dc=foo,dc=at                  |
| ldapBaseGroups                | o=bar,dc=foo,dc=at                          |
| ldapBaseUsers                 | ou=people,o=Staff,o=bar,dc=foo,dc=at        |
| ldapCacheTTL                  | 600                                         |
| ldapConfigurationActive       | 1                                           |
| ldapDynamicGroupMemberURL     |                                             |
| ldapEmailAttribute            | mail                                        |
| ldapExperiencedAdmin          | 1                                           |
| ldapExpertUUIDGroupAttr       |                                             |
| ldapExpertUUIDUserAttr        |                                             |
| ldapExpertUsernameAttr        |                                             |
| ldapGroupDisplayName          | cn                                          |
| ldapGroupFilter               |                                             |
| ldapGroupFilterGroups         |                                             |
| ldapGroupFilterMode           | 1                                           |
| ldapGroupFilterObjectclass    | posixGroup                                  |
| ldapGroupMemberAssocAttr      | uniqueMember                                |
| ldapHost                      | ldaps://ldap.foo.at                         |
| ldapIgnoreNamingRules         |                                             |
| ldapLoginFilter               | (&(|(objectclass=inetOrgPerson))(uid=%uid)) |
| ldapLoginFilterAttributes     |                                             |
| ldapLoginFilterEmail          | 0                                           |
| ldapLoginFilterMode           | 1                                           |
| ldapLoginFilterUsername       | 1                                           |
| ldapNestedGroups              | 0                                           |
| ldapOverrideMainServer        | 0                                           |
| ldapPagingSize                | 500                                         |
| ldapPort                      | 636                                         |
| ldapQuotaAttribute            |                                             |
| ldapQuotaDefault              |                                             |
| ldapTLS                       | 0                                           |
| ldapUserDisplayName           | cn                                          |
| ldapUserDisplayName2          |                                             |
| ldapUserFilter                | (|(objectclass=inetOrgPerson))              |
| ldapUserFilterGroups          |                                             |
| ldapUserFilterMode            | 1                                           |
| ldapUserFilterObjectclass     | inetOrgPerson                               |
| ldapUuidGroupAttribute        | auto                                        |
| ldapUuidUserAttribute         | auto                                        |
| turnOffCertCheck              | 0                                           |
| useMemberOfToDetectMembership | 1                                           |
+-------------------------------+---------------------------------------------+

ownCloud log (data/owncloud.log)

15GB?

The text was updated successfully, but these errors were encountered:

PVince81 · 2017-04-05T13:52:27Z

Check "oc_jobs", you probably have a huge backlog of tasks that cron didn't run.

Running ajax cron once isn't enough.
You might want to manually run it several times until all "oc_jobs" have either disappeared (the one-shot ones) or have a recent timestamp.

umlaeute · 2017-04-05T13:59:46Z

@PVince81 could you be a bit more specific about what you mean with

check "oc_jobs"

(keep in mind not everybody is developing owncloud as their dayjob)

PVince81 · 2017-04-05T14:00:59Z

select * from oc_jobs from the database

umlaeute · 2017-04-05T14:21:30Z

ok, so the backlog is indeed rather huge (117791 unrun jobs). most of these have a last_run value of 0.

how come this has happened?
why is using AJAX not enough?
running /owncloud/cron.php will remove exactly one job.
- the documentation suggests to run this script every 15 minutes which means that i would have to run it for the next 3+ years.
- i don't think that my owncloud instance is that old.
so how could this have happened in the first place?

PVince81 · 2017-04-05T14:24:29Z

ajax is not enough because it doesn't run often enough, known issue: #20380

Ajax cron used to be enough in older OC versions but more and more processing as been moved to cron over newer versions which makes this worse.

umlaeute · 2017-04-05T14:34:54Z

so:

shouldn't the administrator be warned in the webinterface that using AJAX-cron might not be enough (obviously a better strategy would be to fix the underlying issue)
shouldn't the webinterface tell the admin in any case that there is a backlog?
shouldn't there be an option to manually run the entire backlog (or parts thereof; running 120000 jobs might take a while and could effectively take the server offline)

PVince81 · 2017-04-05T14:41:29Z

Seems only the documentation states it's the least reliable: https://doc.owncloud.org/server/9.1/admin_manual/configuration_server/background_jobs_configuration.html?highlight=cron#cron-jobs

Maybe there should be a bigger warning, especially when the backlog is getting bigger.

Moved your suggestions to a new ticket: #27574

umlaeute · 2017-04-05T14:56:37Z

ah i now see that running php -f /var/www/owncloud/cron.php will indeed clean the entire queue, whereas webcron (curl https://mycloud/owncloud/cron.php) will only remove a single item.

this is not obvious from the docs.

as for the documentation on ajax-cron, it indeed does mention that this is the "least preferred" method, but i was not aware that any of the use-cases where ajax might become problematic applied to me, i just discarded that warning. (esp. i was not aware that i ever enabled an "activity app" on purpose; it is now clear to me that this is a bog standard/default application)

ghost · 2017-04-05T15:30:40Z

@umlaeute

this is not obvious from the docs

I think you can post suggestions / improvements to that documentation over at: https://github.com/owncloud/documentation/issues

lock · 2019-08-01T06:00:54Z

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.

PVince81 closed this as completed Apr 5, 2017

PVince81 mentioned this issue Apr 5, 2017

Ajax cron problems #27574

Closed

umlaeute mentioned this issue Apr 6, 2017

clarify the preference for cron jobs owncloud-archive/documentation#2988

Closed

ghost mentioned this issue Apr 16, 2017

Never ending loading wheel; Sync stopped working. #27641

Closed

ownclouders added the status/STALE label Dec 21, 2017

lock bot locked as resolved and limited conversation to collaborators Aug 1, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fast growing logfile due to "file not found" errors #27567

fast growing logfile due to "file not found" errors #27567

umlaeute commented Apr 5, 2017

PVince81 commented Apr 5, 2017

umlaeute commented Apr 5, 2017

PVince81 commented Apr 5, 2017

umlaeute commented Apr 5, 2017

PVince81 commented Apr 5, 2017

umlaeute commented Apr 5, 2017

PVince81 commented Apr 5, 2017

umlaeute commented Apr 5, 2017

ghost commented Apr 5, 2017

lock bot commented Aug 1, 2019

fast growing logfile due to "file not found" errors #27567

fast growing logfile due to "file not found" errors #27567

Comments

umlaeute commented Apr 5, 2017

quick logfile analysis

cron

Server configuration

LDAP configuration (delete this part if not used)

ownCloud log (data/owncloud.log)

PVince81 commented Apr 5, 2017

umlaeute commented Apr 5, 2017

PVince81 commented Apr 5, 2017

umlaeute commented Apr 5, 2017

PVince81 commented Apr 5, 2017

umlaeute commented Apr 5, 2017

PVince81 commented Apr 5, 2017

umlaeute commented Apr 5, 2017

ghost commented Apr 5, 2017

lock bot commented Aug 1, 2019