Owncloud.log goes crazy.

[msrv]

Hi,
as advised on the owncloud forum, i am opening a ticket here.

A few weeks ago (after 9 or 9.0.1 upgrade, can't really tell), the admin panel of my owncloud installation became inaccessible. If i try to access it, the whole server appliance freezes, gives a 504 gateway timeout and needs to be stopped and then started again (restart alone does not work). I will describe in detail:

Steps to reproduce

1. Log on, try to access admin panel
2. tail -f owncloud.log
3. wait and see it grow to 50 + mb in minutes, eats up my ram.

Expected behaviour
Tell us what should happen

admin panel should open, no error should be present

Actual behaviour
Tell us what happens instead

log file is spammed within seconds and now looks like this:

{"reqId":"IVGC+Iesg4A2EMGc9UmP","remoteAddr":"","app":"core","message":"Error while running background job (class: OCA\\DAV\\CardDAV\\SyncJob, arguments: ): {\"Exception\":\"Doctrine\\\\DBAL\\\\Exception\\\\DriverException\",\"Message\":\"An exception occurred while executing 'UPDATEoc_cardsSETcarddata= ?,lastmodified= ?,size= ?,etag= ? WHERE (uri= ?) AND (addressbookid= ?)' with params [\\\"BEGIN:VCARD\\\\r\\\\nVERSION:3.0\\\\r\\\\nPRODID:-\\\\\\\/\\\\\\\/Sabre\\\\\\\/\\\\\\\/Sabre VObject 3.5.0...

And so on. The logfile is HUGE and i cannot really extract useful information from it.

Server configuration

Operating system:
Debian Jessie with apparmor (makes no difference if enabled or disabled completely), /srv is a separate parition with nosuid, nodev, noexec.

Web server:
Nginx 1.1.10 + Naxsi (disabled or enabled or not compiled makes no difference) + Php5 - FPM, all behind SSLH as transparent proxy

Database:
MariaDB 15.1

PHP version:
5.6.20

ownCloud version: (see ownCloud admin page)
9.0.2

Updated from an older ownCloud or fresh install:
Updated

Where did you install ownCloud from:
tarball from websites

Signing status (ownCloud 9.0 and above):
dont know what this means

Login as admin user into your ownCloud and access 
http://example.com/index.php/settings/integrity/failed 
paste the results here.
It says "No errors have been found."

List of activated apps:
Enabled:

• comments: 0.2
• dav: 0.1.6
• federatedfilesharing: 0.1.0
• 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
• provisioning_api: 0.4.1
• templateeditor: 0.1

**The content of config/config.php:**
`{
    "system": {
        "instanceid": "ID",
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "trusted_domains": [
            "IP",
            "URL"
        ],
        "datadirectory": "\/srv\/oc-data",
        "overwrite.cli.url": "https:\/\/SERVER_URL\/",
        "dbtype": "mysql",
        "version": "9.0.2.2",
        "dbname": "oc_db",
        "dbhost": "localhost",
        "dbtableprefix": "oc_",
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "logtimezone": "Europe\/Berlin",
        "installed": true,
        "memcache.local": "\\OC\\Memcache\\Redis",
        "filelocking.enabled": "true",
        "memcache.distributed": "\\OC\\Memcache\\Redis",
        "memcache.locking": "\\OC\\Memcache\\Redis",
        "redis": {
            "host": "localhost",
            "port": 6379,
            "timeout": 0,
            "dbindex": 0
        },
        "mail_from_address": "webmaster",
        "mail_smtpmode": "php",
        "mail_domain": "SERVER_URL",
        "enable_previews": "true",
        "loglevel": 1,
        "maintenance": false,
        "theme": ""
    }
}
`

**Are you using external storage, if yes which one:** local/smb/sftp/...
sshfs mount on /media

**Are you using encryption:** yes/no
no
**Are you using an external user-backend, if yes which one:** LDAP/ActiveDirectory/Webdav/...
no

Client configuration

Browser:
Firefox latest
Operating system:
Windows 10

Logs

Web server error log

error-log.txt

ownCloud log (data/owncloud.log)

owncloud-log.txt

[RobinMcCorkell]

@DeepDiver1975 @PVince81 There are two problems here, one is that we don't trim the string when logging, resulting in stupidly long messages like those shown here (caused by an image embedded in base64 in the vcard). I'd suggest when logging DB errors (I believe stack traces already do this?) we trim any parameters to a sensible length?

[DeepDiver1975]

I'd suggest when logging DB errors (I believe stack traces already do this?) we trim any parameters to a sensible length?

Pull request welcome

[RobinMcCorkell]

SQLSTATE[42000]: Syntax error or access violation: 1118 The size of BLOB\\\/TEXT data inserted in one transaction is greater than 10% of redo log size. Increase the redo log size using innodb_log_file_size.

[DeepDiver1975]

Okay - I guess this is because the avatar image is just hugh .... we need to limit this ...

@msrv any idea what the size of the avatar of that one user is which is causing the error?

[msrv]

Thank you for your replys!
DeepDiver1975, i did a quick du -sch and it returned mutiple avatar files:

root@vsrv23643:/srv/oc-data/USERDATA# du -sch avatar.*
8,0K avatar.182.jpg
4,0K avatar.1.jpg
12K avatar.218.jpg
4,0K avatar.32.jpg
4,0K avatar.35.jpg
4,0K avatar.42.jpg
4,0K avatar.64.jpg
588K avatar.jpg
628K insgesamt

[Dallo71]

I've the same issue.
Seem something try to update the carddata field in the oc_cards table by a vcf larger than 16MB exceding the the mysql my.cnf settings. So an exception is generated and the entire 16MB+ vcf is reported in the log file. Retry this operation make the log file huge in a while.

I've temporary resolved settings all my.cnf 16MB reference to 32MB and restart mysql.

By phpMyAdmin I saved the big blog fields and try to extract the jpeg stored in vcard by an online extractor (http://www.docx2doc.com/convert/vcf-to-jpg.html)

There are 2 stranghe things:

1. The extracted jpeg image is about 300KB instead 16MB
2. The extracted jpeg image seems to be an image of a sheet page containing a table with the followin information:

                                              Sheet1
____________________________________________________________________________
WARNING | FORMATTED NAME                            | NAME PREFIX | NAME FIRST
----------------------------------------------------------------------------
        | Name SURNAME ([email protected]) |             | Name



                                              Page1

You can download the extracted and decoded MIME-Base64 300KB jpeg file: https://moredrive.unimore.it/index.php/s/pz3OlDj3zh9ZIgV

Now the questions are:

1. Wich ownCloud module try to make this DB update?
2. Why in the vcf there is an image of a sheet page and who cretate this page and the following image of it?
3. Why the vcf is so bigger compared to the extracted jpeg image?
4. Why this behavior affect only certain users? There are only few users with the carddata field populated by a vcf containing the sheet image and just some with the huge vcf

Someone is able to give me an answer or put me in the right direction to solve this problem?

Thank You

[RobinMcCorkell]

@Dallo71 That JPG that you have is not the image stored as an avatar within the VCF, but rather just a representation of some of the data from the VCF in an image format (hence the VCF to JPG converter). You have at some point uploaded an image as an avatar for a contact, which was too large, so updating the database failed. The bug with ownCloud here is that we then dump the entire thing to the log, which is bad. Also, we don't check the avatar size.

[lock]

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.