Calendar data database migration failure

[yodax]

Steps to reproduce

1. Migrate data from sqlite to postgresql
2. use occ db:convert-type

Expected behaviour

Data should be migrated

Actual behaviour

An error occured:

In AbstractPostgreSQLDriver.php line 79:
                                                                                                                      
  An exception occurred while executing 'INSERT INTO "oc_calendarobjects_props" ("id", "calendarid", "objectid", "na  
  me", "parameter", "value", "calendartype") VALUES(?, ?, ?, ?, ?, ?, ?)' with params ["5955", "14", "4337", "DESCRI  
  PTION", null, "\x48\x69\x20\x43\x6f\x73\x6d\x69\x6e\x2c\x0a\x20\x0a\x57\x65\x20\x6e\x65\x65\x64\x20\x74\x6f\x20\x6  
  6\x69\x6c\x6c\x20\x69\x6e\x20\x74\x68\x65\x20\x4c\x41\x43\x46\x20\x73\x70\x72\x65\x61\x64\x73\x68\x65\x65\x74\x73\  
  x20\x66\x6f\x72\x20\x73\x6f\x6d\x65\x20\x6f\x66\x20\x74\x68\x65\x20\x6d\x61\x72\x6b\x65\x74\x20\x72\x69\x73\x6b\x2  
  0\x73\x79\x73\x74\x65\x6d\x73\x20\x28\x56\x61\x72\x69\x6d\x2c\x20\x52\x41\x4d\x2c\x20\x50\x46\x41\x2c\x20\x4c\x69\  
  x63\x6f\x73\x29\x2e\x0a\x20\x0a\x57\x65\xe2\x80\x99\x64\x20\x61\x70\x70\x72\x65\x63\x69\x61\x74\x65\x20\x73\x6f\x6  
  d\x65\x20\x6f\x66\x20\x79\x6f\x75\x72\x20\x74\x69\x6d\x65\x20\x74\x6f\x20\x67\x69\x76\x65\x20\x75\x73\x20\x73\x6f\  
  x6d\x65\x20\x67\x75\x69\x64\x61\x6e\x63\x65\x20\x61\x62\x6f\x75\x74\x20\x66\x69\x6c\x6c\x69\x6e\x67\x20\x69\x6e\x2  
  0\x74\x68\x65\x20\x73\x68\x65\x65\x74\x73\x2e\x0a\x20\x0a\x49\x20\x68\x61\x76\x65\x6e\xe2\x80\x99\x74\x20\x62\x6f\  
  x6f\x6b\x65\x64\x20\x61\x20\x6d\x65\x65\x74\x69\x6e\x67\x20\x72\x6f\x6f\x6d\x20\x66\x6f\x72\x20\x74\x68\x69\x73\x2  
  0\xe2", "0"]:                                                                                                       
                                                                                                                      
  SQLSTATE[22021]: Character not in repertoire: 7 ERROR:  invalid byte sequence for encoding "UTF8": 0xe2             
                                                                                                                      

In PDOStatement.php line 119:
                                                                                                           
  SQLSTATE[22021]: Character not in repertoire: 7 ERROR:  invalid byte sequence for encoding "UTF8": 0xe2  
                                                                                                           

In PDOStatement.php line 117:
                                                                                                           
  SQLSTATE[22021]: Character not in repertoire: 7 ERROR:  invalid byte sequence for encoding "UTF8": 0xe2  
                                                                                                           

Calendar app

Calendar app version: 1.7.1

CalDAV-clients used: N/A

Client configuration

Browser: ssh

Operating system: Ubuntu 18.04

Server configuration

Operating system: Ubuntu 18.04

Web server: nginx

Database: SQLite => PostgreSQL

PHP version: 7.2

Nextcloud Version: 17.0.1

Updated from an older installed version or fresh install:

List of activated apps:

Enabled:
  - accessibility: 1.3.0
  - activity: 2.10.1
  - calendar: 1.7.1
  - cloud_federation_api: 1.0.0
  - comments: 1.7.0
  - contacts: 3.1.6
  - dav: 1.13.0
  - federatedfilesharing: 1.7.0
  - federation: 1.7.0
  - files: 1.12.0
  - files_external: 1.8.0
  - files_pdfviewer: 1.6.0
  - files_rightclick: 0.15.1
  - files_sharing: 1.9.0
  - files_trashbin: 1.7.0
  - files_versions: 1.10.0
  - files_videoplayer: 1.6.0
  - gallery: 18.4.0
  - logreader: 2.2.0
  - lookup_server_connector: 1.5.0
  - nextcloud_announcements: 1.6.0
  - notifications: 2.5.0
  - oauth2: 1.5.0
  - password_policy: 1.7.0
  - privacy: 1.1.0
  - provisioning_api: 1.7.0
  - recommendations: 0.5.0
  - serverinfo: 1.7.0
  - sharebymail: 1.7.0
  - support: 1.0.1
  - survey_client: 1.5.0
  - systemtags: 1.7.0
  - text: 1.1.1
  - theming: 1.8.0
  - twofactor_backupcodes: 1.6.0
  - updatenotification: 1.7.0
  - user_external: 0.7.0
  - viewer: 1.2.0
  - workflowengine: 1.7.0
Disabled:
  - admin_audit
  - encryption
  - firstrunwizard
  - user_ldap

Nextcloud configuration:

{
    "system": {
        "datadirectory": "***REMOVED SENSITIVE VALUE***",
        "instanceid": "***REMOVED SENSITIVE VALUE***",
        "forcessl": true,
        "overwritewebroot": "\/cloud",
        "overwrite.cli.url": "\/cloud",
        "user_backends": [
            {
                "class": "OC_User_IMAP",
                "arguments": [
                    "127.0.0.1",
                    143,
                    null
                ]
            }
        ],
        "memcache.local": "\\OC\\Memcache\\APCu",
        "memcached_servers": [
            [
                "localhost",
                11211
            ]
        ],
        "mail_smtpmode": "sendmail",
        "mail_smtpsecure": "",
        "mail_smtpauthtype": "LOGIN",
        "mail_smtpauth": false,
        "mail_smtphost": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpport": "",
        "mail_smtpname": "***REMOVED SENSITIVE VALUE***",
        "mail_smtppassword": "***REMOVED SENSITIVE VALUE***",
        "mail_from_address": "***REMOVED SENSITIVE VALUE***",
        "mail_domain": "***REMOVED SENSITIVE VALUE***",
        "logtimezone": "Europe\/Amsterdam",
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "trusted_domains": [
            "box.kroes.email"
        ],
        "dbtype": "sqlite3",
        "version": "17.0.1.1",
        "installed": true,
        "loglevel": 2,
        "maintenance": false,
        "trashbin_retention_obligation": "auto",
        "logdateformat": "Y-m-d H:i:s"
    }
}

[georgehrke]

@nickvergessen Any idea what causes this?

[yodax]

I was doubting if it should be in server or in calendar thanks for the move 👍

I ran the query for that object on the sqllite database, everything in there is human readable.

[tcitworld]

Maybe the PostgreSQL database created doesn't handle UTF8 ?

[yodax]

It was created with:

CREATE DATABASE nextcloud TEMPLATE template0 ENCODING 'UNICODE';

[yodax]

What might be good to mention is that right after the upgrade to 16.0.6 from 16.0.5 I started having long running cron jobs. So long they wouldn't finish. The whole server wouldn't respond and the logs showed that the sqlite database was locked. Terminating the cron job would solve the issue. It would run fine for about a day then started locking again.

I suspect this is to do with the external storage. Before 16.0.6 it wouldn't index files on the S3 storage that wasn't uploaded via nextcloud (which is fine, I don't need it to). Since 16.0.6 it started doing that. Since that is around 500gb of data in many thousands of files I think that is a bit too much for the sqllite database. (all of this is speculation) I since disabled this in the external storage configuration, but it still seems to be doing it regardless.

That triggered me to spin up a database psql 11 on a separate machine to do a migration and see if the problem would go away.

[yodax]

This is all running on a standard mail-in-a-box with PR mail-in-a-box/mailinabox#1676 applied.

[yodax]

This is the error message I'm seeing for the cron job. Nothing before it from the local machine. (just other login attempts etc)

{"reqId":"mGMm4a19FaEJ14nkMUvr","level":3,"time":"2019-11-17 21:18:01","remoteAddr":"","user":"--","app":"cron","method":"","url":"\/cloud\/cron.php","message":{"Exception":"Doctrine\\DBAL\\Exception\\LockWaitTimeoutException","Message":"An exception occurred while executing 'DELETE FROM \"oc_appconfig\" WHERE (\"appid\" = ?) AND (\"configkey\" = ?)' with params [\"core\", \"cronErrors\"]:\n\nSQLSTATE[HY000]: General error: 5 database is locked","Code":0,"Trace":[{"file":"\/usr\/local\/lib\/owncloud\/3rdparty\/doctrine\/dbal\/lib\/Doctrine\/DBAL\/DBALException.php","line":169,"function":"convertException","class":"Doctrine\\DBAL\\Driver\\AbstractSQLiteDriver","type":"->","args":["An exception occurred while executing 'DELETE FROM \"oc_appconfig\" WHERE (\"appid\" = ?) AND (\"configkey\" = ?)' with params [\"core\", \"cronErrors\"]:\n\nSQLSTATE[HY000]: General error: 5 database is locked",{"errorInfo":["HY000",5,"database is locked"],"__class__":"Doctrine\\DBAL\\Driver\\PDOException"}]},{"file":"\/usr\/local\/lib\/owncloud\/3rdparty\/doctrine\/dbal\/lib\/Doctrine\/DBAL\/DBALException.php","line":145,"function":"wrapException","class":"Doctrine\\DBAL\\DBALException","type":"::","args":[{"__class__":"Doctrine\\DBAL\\Driver\\PDOSqlite\\Driver"},{"errorInfo":["HY000",5,"database is locked"],"__class__":"Doctrine\\DBAL\\Driver\\PDOException"},"An exception occurred while executing 'DELETE FROM \"oc_appconfig\" WHERE (\"appid\" = ?) AND (\"configkey\" = ?)' with params [\"core\", \"cronErrors\"]:\n\nSQLSTATE[HY000]: General error: 5 database is locked"]},{"file":"\/usr\/local\/lib\/owncloud\/3rdparty\/doctrine\/dbal\/lib\/Doctrine\/DBAL\/Connection.php","line":1063,"function":"driverExceptionDuringQuery","class":"Doctrine\\DBAL\\DBALException","type":"::","args":[{"__class__":"Doctrine\\DBAL\\Driver\\PDOSqlite\\Driver"},{"errorInfo":["HY000",5,"database is locked"],"__class__":"Doctrine\\DBAL\\Driver\\PDOException"},"DELETE FROM \"oc_appconfig\" WHERE (\"appid\" = ?) AND (\"configkey\" = ?)",{"1":"core","2":"cronErrors"}]},{"file":"\/usr\/local\/lib\/owncloud\/lib\/private\/DB\/Connection.php","line":216,"function":"executeUpdate","class":"Doctrine\\DBAL\\Connection","type":"->","args":["DELETE FROM \"oc_appconfig\" WHERE (\"appid\" = ?) AND (\"configkey\" = ?)",["core","cronErrors"],[2,2]]},{"file":"\/usr\/local\/lib\/owncloud\/3rdparty\/doctrine\/dbal\/lib\/Doctrine\/DBAL\/Query\/QueryBuilder.php","line":203,"function":"executeUpdate","class":"OC\\DB\\Connection","type":"->","args":["DELETE FROM \"oc_appconfig\" WHERE (\"appid\" = :app) AND (\"configkey\" = :configkey)",{"app":"core","configkey":"cronErrors"},[]]},{"file":"\/usr\/local\/lib\/owncloud\/lib\/private\/DB\/QueryBuilder\/QueryBuilder.php","line":214,"function":"execute","class":"Doctrine\\DBAL\\Query\\QueryBuilder","type":"->","args":[]},{"file":"\/usr\/local\/lib\/owncloud\/lib\/private\/AppConfig.php","line":243,"function":"execute","class":"OC\\DB\\QueryBuilder\\QueryBuilder","type":"->","args":[]},{"file":"\/usr\/local\/lib\/owncloud\/lib\/private\/AllConfig.php","line":224,"function":"deleteKey","class":"OC\\AppConfig","type":"->","args":["core","cronErrors"]},{"file":"\/usr\/local\/lib\/owncloud\/lib\/base.php","line":680,"function":"deleteAppValue","class":"OC\\AllConfig","type":"->","args":["core","cronErrors"]},{"file":"\/usr\/local\/lib\/owncloud\/lib\/base.php","line":1081,"function":"init","class":"OC","type":"::","args":[]},{"file":"\/usr\/local\/lib\/owncloud\/cron.php","line":41,"args":["\/usr\/local\/lib\/owncloud\/lib\/base.php"],"function":"require_once"}],"File":"\/usr\/local\/lib\/owncloud\/3rdparty\/doctrine\/dbal\/lib\/Doctrine\/DBAL\/Driver\/AbstractSQLiteDriver.php","Line":25,"Previous":{"Exception":"Doctrine\\DBAL\\Driver\\PDOException","Message":"SQLSTATE[HY000]: General error: 5 database is locked","Code":"HY000","Trace":[{"file":"\/usr\/local\/lib\/owncloud\/3rdparty\/doctrine\/dbal\/lib\/Doctrine\/DBAL\/Connection.php","line":1054,"function":"execute","class":"Doctrine\\DBAL\\Driver\\PDOStatement","type":"->","args":[]},{"file":"\/usr\/local\/lib\/owncloud\/lib\/private\/DB\/Connection.php","line":216,"function":"executeUpdate","class":"Doctrine\\DBAL\\Connection","type":"->","args":["DELETE FROM \"oc_appconfig\" WHERE (\"appid\" = ?) AND (\"configkey\" = ?)",["core","cronErrors"],[2,2]]},{"file":"\/usr\/local\/lib\/owncloud\/3rdparty\/doctrine\/dbal\/lib\/Doctrine\/DBAL\/Query\/QueryBuilder.php","line":203,"function":"executeUpdate","class":"OC\\DB\\Connection","type":"->","args":["DELETE FROM \"oc_appconfig\" WHERE (\"appid\" = :app) AND (\"configkey\" = :configkey)",{"app":"core","configkey":"cronErrors"},[]]},{"file":"\/usr\/local\/lib\/owncloud\/lib\/private\/DB\/QueryBuilder\/QueryBuilder.php","line":214,"function":"execute","class":"Doctrine\\DBAL\\Query\\QueryBuilder","type":"->","args":[]},{"file":"\/usr\/local\/lib\/owncloud\/lib\/private\/AppConfig.php","line":243,"function":"execute","class":"OC\\DB\\QueryBuilder\\QueryBuilder","type":"->","args":[]},{"file":"\/usr\/local\/lib\/owncloud\/lib\/private\/AllConfig.php","line":224,"function":"deleteKey","class":"OC\\AppConfig","type":"->","args":["core","cronErrors"]},{"file":"\/usr\/local\/lib\/owncloud\/lib\/base.php","line":680,"function":"deleteAppValue","class":"OC\\AllConfig","type":"->","args":["core","cronErrors"]},{"file":"\/usr\/local\/lib\/owncloud\/lib\/base.php","line":1081,"function":"init","class":"OC","type":"::","args":[]},{"file":"\/usr\/local\/lib\/owncloud\/cron.php","line":41,"args":["\/usr\/local\/lib\/owncloud\/lib\/base.php"],"function":"require_once"}],"File":"\/usr\/local\/lib\/owncloud\/3rdparty\/doctrine\/dbal\/lib\/Doctrine\/DBAL\/Driver\/PDOStatement.php","Line":119,"Previous":{"Exception":"PDOException","Message":"SQLSTATE[HY000]: General error: 5 database is locked","Code":"HY000","Trace":[{"file":"\/usr\/local\/lib\/owncloud\/3rdparty\/doctrine\/dbal\/lib\/Doctrine\/DBAL\/Driver\/PDOStatement.php","line":117,"function":"execute","class":"PDOStatement","type":"->","args":[null]},{"file":"\/usr\/local\/lib\/owncloud\/3rdparty\/doctrine\/dbal\/lib\/Doctrine\/DBAL\/Connection.php","line":1054,"function":"execute","class":"Doctrine\\DBAL\\Driver\\PDOStatement","type":"->","args":[]},{"file":"\/usr\/local\/lib\/owncloud\/lib\/private\/DB\/Connection.php","line":216,"function":"executeUpdate","class":"Doctrine\\DBAL\\Connection","type":"->","args":["DELETE FROM \"oc_appconfig\" WHERE (\"appid\" = ?) AND (\"configkey\" = ?)",["core","cronErrors"],[2,2]]},{"file":"\/usr\/local\/lib\/owncloud\/3rdparty\/doctrine\/dbal\/lib\/Doctrine\/DBAL\/Query\/QueryBuilder.php","line":203,"function":"executeUpdate","class":"OC\\DB\\Connection","type":"->","args":["DELETE FROM \"oc_appconfig\" WHERE (\"appid\" = :app) AND (\"configkey\" = :configkey)",{"app":"core","configkey":"cronErrors"},[]]},{"file":"\/usr\/local\/lib\/owncloud\/lib\/private\/DB\/QueryBuilder\/QueryBuilder.php","line":214,"function":"execute","class":"Doctrine\\DBAL\\Query\\QueryBuilder","type":"->","args":[]},{"file":"\/usr\/local\/lib\/owncloud\/lib\/private\/AppConfig.php","line":243,"function":"execute","class":"OC\\DB\\QueryBuilder\\QueryBuilder","type":"->","args":[]},{"file":"\/usr\/local\/lib\/owncloud\/lib\/private\/AllConfig.php","line":224,"function":"deleteKey","class":"OC\\AppConfig","type":"->","args":["core","cronErrors"]},{"file":"\/usr\/local\/lib\/owncloud\/lib\/base.php","line":680,"function":"deleteAppValue","class":"OC\\AllConfig","type":"->","args":["core","cronErrors"]},{"file":"\/usr\/local\/lib\/owncloud\/lib\/base.php","line":1081,"function":"init","class":"OC","type":"::","args":[]},{"file":"\/usr\/local\/lib\/owncloud\/cron.php","line":41,"args":["\/usr\/local\/lib\/owncloud\/lib\/base.php"],"function":"require_once"}],"File":"\/usr\/local\/lib\/owncloud\/3rdparty\/doctrine\/dbal\/lib\/Doctrine\/DBAL\/Driver\/PDOStatement.php","Line":117}},"CustomMessage":"--"},"userAgent":"--","version":"17.0.1.1"}

[yodax]

I've removed the s3 share with 700k files on it. This solved the cron issue.

I've deleted the record in oc_calendarobjects_props with id 5955 and this solved the migration issue. Which I reverted since everything was working fine again with sqlite.

[kesselb]

I suspect this is to do with the external storage. Before 16.0.6 it wouldn't index files on the S3 storage that wasn't uploaded via nextcloud (which is fine, I don't need it to). Since 16.0.6 it started doing that. Since that is around 500gb of data in many thousands of files I think that is a bit too much for the sqllite database. (all of this is speculation) I since disabled this in the external storage configuration, but it still seems to be doing it regardless.

Oh 🙈 #14913 that was actually a bug ;) Good to know you solved the issue 👍