Gateway imap error - Invalid size tag received:

Galen

As i’ve had no response to my post for help to fix a user i’ve been looking at other options. I’ve created a second user and am trying to copy the original mailbox to the new “clean” user with imapsync.

Imapsync fails with errors thrown when trying to write to the new user mailbox. I’m seeing a lot of these in gateway.log:

Sat Jul  1 23:26:32 2017: [error  ] [ 3514] Invalid size tag received: \rtf1\ansi\ansicpg1252\fromtext \fbidis \deff0{\fonttbl
Sat Jul  1 23:28:32 2017: [error  ] [ 3514] Client disconnected
Sat Jul  1 23:29:25 2017: [error  ] [ 3516] Invalid size tag received: \rtf1\ansi\ansicpg1252\fromtext \fbidis \deff0{\fonttbl
Sat Jul  1 23:31:25 2017: [error  ] [ 3516] Client disconnected

What would trigger Invalid size tag received from a record that exits and can seemingly be read ok from the original mailbox via imap?

G

Galen

I’ve done more testing with this and i think there’s something not quite right in core 8.4.0-1004-174.1.

I’ve got a ZCP 7.2.5 and KC 8.4 test system loaded from the same sql dump and synced attachments. ZCP is on Debian 7 and KC on Debian 9.

On both systems:
An existing user account foo is renamed to foo.old.
A new user account foo is created.
imapsync is called to copy all foo.old folders and messages to the new foo account.

The ZCP system completes the transfer and reports 2 errors out of nearly 40,000 messages transferred.

The KC system hits the 50 error limit after a while and quits.
Each of the errors has “couldn’t append (Subject:[]) to folder FOLDERNAME: 13 NO APPEND error saving message” reported by the imapsync program and for each error the server.log file has an entry with large amounts of non printable ascii that start with:

Mon Jul  3 01:16:25 2017: [error  ] SQL [00000320] Failed: MySQL server has gone away, Query Size: 337176, Query: "REPLACE INTO properties (hierarchyid,tag,type,properties.val_ulong,properties.val_string,properties.val_binary,properties.val_double,properties.val_longint,properties.val_hi,properties.val_lo) VALUES(10339194,34062,30,null,'\"Thu, 1 Jan 1970 00:00:00 +0000\" NIL NIL NIL NIL NIL NIL NIL NIL NIL',null,null,null,null,null),(10339194,26,30,null,'IPM.Note',null,null,null,null,null),(10339194,125,30,null,'^OExif',null,null,null,null,null),(10339194,3590,64,null,null,null,null,null,30345111,3431510144),(10339194,3591,3,3,null,null,null,null,null,null),(10339194,3592,3,666166,null,null,null,null,null,null),(10339194,4096,30,null,'\r\n^F^G^K^L^K\r\n^L   \r\n\r\n        ^A^A^A^A^B^B^B^D^B^B^D  ^F^E^F                                                                                                                                                                                                                                                                                                                                                                                                          ^Df^Q^H^D^F`^C^A\"^B^Q^A^C^Q^A^A^A^E^A^A^A^A^A^A^A^B^C^D^E^F^G^H        \r\n^K^P^B^A^C^C^B^D^C^E^E^D^D^A}^A^B^C^D^Q^E^R!1A^F^SQa^G\"q^T2^H#B^UR$3br     \r\n^V^W^X^Y\Z%&\'()*456789:CDEFGHIJSTUVWXYZcdefghijstuvwx

And:

Mon Jul  3 01:16:25 2017: [error  ] KDatabase::_Update() query failed: REPLACE INTO properties (hierarchyid,tag,type,properties.val_ulong,properties.val_string,properties.val_binary,properties.val_double,properties.val_longint,properties.val_hi,properties.val_lo) VALUES(10339194,34062,30,null,'\"Thu, 1 Jan 1970 00:00:00 +0000\" NIL NIL NIL NIL NIL NIL NIL NIL NIL',null,null,null,null,null),(10339194,26,30,null,'IPM.Note',null,null,null,null,null),(10339194,125,30,null,'^OExif',null,null,null,null,null),(10339194,3590,64,null,null,null,null,null,30345111,3431510144),(10339194,3591,3,3,null,null,null,null,null,null),(10339194,3592,3,666166,null,null,null,null,null,null),(10339194,4096,30,null,'\r\n^F^G^K^L^K\r\n^L       \r\n\r\n        ^A^A^A^A^B^B^B^D^B^B^D  ^F^E^F                                                                                                                                                                                                                                                                                                                                                                                                          ^Df^Q^H^D^F`^C^A\"^B^Q^A^C^Q^A^A^A^E^A^A^A^A^A^A^A^B^C^D^E^F^G^H        \r\n^K^P^B^A^C^C^B^D^C^E^E^D^D^A}^A^B^C^D^Q^E^R!1A^F^SQa^G\"q^T2^H#B^UR$3br     \r\n^V^W^X^Y\Z%&\'()*456789:CDEFGHIJSTUVWXYZcdefghijstuvwx

Something must be broken to give those kinds of log entry?

G

fbartels

@Galen did the mysql server “go away” as given by the first log line? Anything in the syslog or the logging of mysql?

Galen

As far as i can see mysql itself didn’t go away.

To provide log details of the failures i’ve isolated 3 of the problem emails and placed them in a folder ‘BREAKS-KOPANO’
I stopped and started kopano-server and mysql.
Ran imapsync with the option --folder ‘BREAKS-KOPANO’ to attempt to sync the single folder.

Attempts are shown for 3 messages all fail.

/var/log/mysql/error.log gives this from the restart

2017-07-05  1:37:05 140190110229056 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.1.23-MariaDB-9+deb9u1'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  Debian 9.0

grep ‘warn|crit|error|sql’ /var/log/syslog -i gives:

Jul  5 01:37:02 kopano mysqld[3638]: 2017-07-05  1:37:02 140190110229056 [Note] /usr/sbin/mysqld (mysqld 10.1.23-MariaDB-9+deb9u1) starting as process 3638 ...

server.log has this:

Wed Jul  5 01:45:20 2017: [ notice] Starting server version 8,4,0,1004, pid 3830
Wed Jul  5 01:45:34 2017: [warning] SQL [00000030] info: Try to reconnect
Wed Jul  5 01:45:34 2017: [error  ] SQL [00000032] Failed: MySQL server has gone away, Query Size: 337176, Query: "REPLACE INTO properties (hierarchyid,tag,type,properties.val_ulong,properties.val_string,properties.val_binary,properties.val_double,properties.val_longint,properties.val_hi,properties.val_lo) VALUES(10341641,34062,30,null,'\"Thu, 1 Jan 1970 00:00:00 +0000\" NIL NIL NIL NIL NIL NIL NIL NIL NIL',null,null,null,null,null),(10341641,26,30,null,'IPM.Note',null,null,null,null,null),(10341641,125,30,null,'Exif',null,null,null,null,null),(10341641,3590,64,null,null,null,null,null,30345111,3431510144),(10341641,3591,3,3,null,null,null,null,null,null),(10341641,3592,3,666166,null,null,null,null,null,null),(10341641,4096,30,null,LOTSOFGARBAGEHERE
Wed Jul  5 01:45:34 2017: [error  ] KDatabase::_Update() query failed: REPLACE INTO properties (hierarchyid,tag,type,properties.val_ulong,properties.val_string,properties.val_binary,properties.val_double,properties.val_longint,properties.val_hi,properties.val_lo) VALUES(10341641,34062,30,null,'\"Thu, 1 Jan 1970 00:00:00 +0000\" NIL NIL NIL NIL NIL NIL NIL NIL NIL',null,null,null,null,null),(10341641,26,30,null,'IPM.Note',null,null,null,null,null),(10341641,125,30,null,'Exif',null,null,null,null,null),(10341641,3590,64,null,null,null,null,null,30345111,3431510144),(10341641,3591,3,3,null,null,null,null,null,null),(10341641,3592,3,666166,null,null,null,null,null,null),(10341641,4096,30,null,LOTSOFGARBAGEHERE
Wed Jul  5 01:45:34 2017: [warning] SQL [00000032] info: Try to reconnect
Wed Jul  5 01:45:34 2017: [warning] SQL [00000033] info: Try to reconnect
Wed Jul  5 01:45:34 2017: [error  ] SQL [00000034] Failed: MySQL server has gone away, Query Size: 381653, Query: "REPLACE INTO properties (hierarchyid,tag,type,properties.val_ulong,properties.val_string,properties.val_binary,properties.val_double,properties.val_longint,properties.val_hi,properties.val_lo) VALUES(10341642,34062,30,null,'\"Thu, 1 Jan 1970 00:00:00 +0000\" NIL NIL NIL NIL NIL NIL NIL NIL NIL',null,null,null,null,null),(10341642,26,30,null,'IPM.Note',null,null,null,null,null),(10341642,125,30,null,'Exif',null,null,null,null,null),(10341642,3590,64,null,null,null,null,null,30345113,3591575552),(10341642,3591,3,3,null,null,null,null,null,null),(10341642,3592,3,763200,null,null,null,null,null,null),(10341642,4096,30,null,LOTSOFGARBAGEHERE
Wed Jul  5 01:45:34 2017: [error  ] KDatabase::_Update() query failed: REPLACE INTO properties (hierarchyid,tag,type,properties.val_ulong,properties.val_string,properties.val_binary,properties.val_double,properties.val_longint,properties.val_hi,properties.val_lo) VALUES(10341642,34062,30,null,'\"Thu, 1 Jan 1970 00:00:00 +0000\" NIL NIL NIL NIL NIL NIL NIL NIL NIL',null,null,null,null,null),(10341642,26,30,null,'IPM.Note',null,null,null,null,null),(10341642,125,30,null,'Exif',null,null,null,null,null),(10341642,3590,64,null,null,null,null,null,30345113,3591575552),(10341642,3591,3,3,null,null,null,null,null,null),(10341642,3592,3,763200,null,null,null,null,null,null),(10341642,4096,30,null,LOTSOFGARBAGEHERE
Wed Jul  5 01:45:34 2017: [warning] SQL [00000034] info: Try to reconnect
Wed Jul  5 01:45:35 2017: [warning] SQL [00000027] info: Try to reconnect
Wed Jul  5 01:45:35 2017: [error  ] SQL [00000036] Failed: MySQL server has gone away, Query Size: 338807, Query: "REPLACE INTO properties (hierarchyid,tag,type,properties.val_ulong,properties.val_string,properties.val_binary,properties.val_double,properties.val_longint,properties.val_hi,properties.val_lo) VALUES(10341643,34062,30,null,'\"Thu, 1 Jan 1970 00:00:00 +0000\" NIL NIL NIL NIL NIL NIL NIL NIL NIL',null,null,null,null,null),(10341643,26,30,null,'IPM.Note',null,null,null,null,null),(10341643,125,30,null,'Exif',null,null,null,null,null),(10341643,3590,64,null,null,null,null,null,30345120,2036804480),(10341643,3591,3,3,null,null,null,null,null,null),(10341643,3592,3,670707,null,null,null,null,null,null),(10341643,4096,30,null,LOTSOFGARBAGEHERE
Wed Jul  5 01:45:35 2017: [error  ] KDatabase::_Update() query failed: REPLACE INTO properties (hierarchyid,tag,type,properties.val_ulong,properties.val_string,properties.val_binary,properties.val_double,properties.val_longint,properties.val_hi,properties.val_lo) VALUES(10341643,34062,30,null,'\"Thu, 1 Jan 1970 00:00:00 +0000\" NIL NIL NIL NIL NIL NIL NIL NIL NIL',null,null,null,null,null),(10341643,26,30,null,'IPM.Note',null,null,null,null,null),(10341643,125,30,null,'Exif',null,null,null,null,null),(10341643,3590,64,null,null,null,null,null,30345120,2036804480),(10341643,3591,3,3,null,null,null,null,null,null),(10341643,3592,3,670707,null,null,null,null,null,null),(10341643,4096,30,null,LOTSOFGARBAGEHERE
Wed Jul  5 01:45:35 2017: [warning] SQL [00000036] info: Try to reconnect

I replaced the non printable with LOTSOFGARBAGEHERE. I can email the complete log with non printable if you need it?

There are no errors logged in the gateway.log.

G

fbartels

@Galen the gateway.log may help understanding the problem, but does not help to reproduce the problem.

A better chance would be to export this specific folder via kopano-backup, like the following:

kopano-backup --user username --log-level=debug --folder BREAKS-KOPANO

The above command will only export the given folder and log everything on debug level. please send the created backup and the generated output of kopano-backup.

If you have a subscription please open up a ticket and let our support reproduce the problem, if you don’t have a subscription please send the data to feedback at kopano dot io and i will have a look when I have some free developer time available.

Galen

I’ve been doing some more testing and i think i have determined what is breaking the imap transfer. Instead of sending the requested message gateway is returning an attachment from another email, hence the binary output.

If i save the email via webapp it too serves an image instead of the message text that is displayed in the view pane.

The same tests on the original ZCP on Debian 7 work as expected.

This leads me to think that the data export<>import process is probably the creating the problem. I’m exporting the working ZCP with mysqldump -p zarafa > zarafa.sql and then importing on the KC system with mysql -p kopano < zarafa.sql.

Because the Kopano install information suggests that the databases are compatible i’m expecting the above inport<>export to work OK.
i can view the image
Is there something else i must do to migrate the data?

G

Galen

Yet more testing with this…

I can successfully transfer the complete 40,000 message mailbox from ZCP 7.2.5 to Dovecot with imapsync, same transfer to KC 8.4 imap fails.

Transferring ZCP 7.2.5 -> Dovecot -> KC 8.4 produces some of the same errors that a direct transfer from ZCP -> KC does.

[error  ] SQL [00000460] Failed: MySQL server has gone away, Query Size: 398187, Query: "REPLACE INTO properties

MySQL hasn’t gone away and there are no errors logged in /var/log/mysql/error.log

@Fbartels i can isolate some of the messages that produce errors into a folder on the source ZCP but i don’t have zarafa-backup to export and send the data to you.

G

fbartels

@Galen said in Gateway imap error - Invalid size tag received::

@Fbartels i can isolate some of the messages that produce errors into a folder on the source ZCP but i don’t have zarafa-backup to export and send the data to you.

you could still configure kopano-backup on your new host to connect to you old zarafa. from the kopano-backup man page:

       --server-socket, -s SOCKET
           Connect to storage server through specified socket.

       --auth-user, -U NAME
           Authenticate as specified user.

       --auth-pass, -P PASS
           Authenticate with specified password.

       --ssl-key, -k FILE
           Specify SSL key file.

       --ssl-pass, -p PASSWORD
           Specify SSL key password.```

Galen

I’ve just sent breaks-kopano.tar over for you.

There are 10 items in the folder from the same sender in the same format.
9 items fail and for comparison 1 transfers successfully.

G

Galen

@fbartels

I’ve tested another user with a smaller malibox and no known issues.
I’ve imported an sql dump and moved attachments over to a fresh install of ZCP 7.2.5.
Backed up the mailbox with kopano-backup from ZCP and then restored into KC 8.4.0~1074-4.1.

The source mailbox had 558 messages in Inbox and the target had 546 after the restore.
I identified the missing 12 from the initial import and moved them into a new folder BREAKS-KOPANO-2 and exported that folder.
Trying to import that single folder export results in one message being imported successfully and the other 11 failing with backup errors like this

2017-07-23 17:37:42,636 - backup - DEBUG - restoring item with sourcekey 019026A9FFA5497A8DB81D23C9A23EE0ACA238000000
2017-07-23 17:37:42,731 - backup - ERROR - Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/kopano/log.py", line 87, in log_exc
    try: yield
  File "/usr/lib/python2.7/dist-packages/kopano_backup/__init__.py", line 635, in restore_folder
    item = folder.create_item(loads=zlib.decompress(db[sourcekey2]), attachments=not self.options.skip_attachments)
  File "/usr/lib/python2.7/dist-packages/kopano/folder.py", line 299, in create_item
    item = _item.Item(self, eml=eml, ics=ics, vcf=vcf, load=load, loads=loads, attachments=attachments, create=True)
  File "/usr/lib/python2.7/dist-packages/kopano/item.py", line 167, in __init__
    self.loads(loads, attachments=attachments)
  File "/usr/lib/python2.7/dist-packages/kopano/item.py", line 936, in loads
    self._load(_pickle_loads(s), attachments)
  File "/usr/lib/python2.7/dist-packages/kopano/item.py", line 930, in _load
    self.mapiobj.SaveChanges(KEEP_OPEN_READWRITE) # XXX needed?
  File "/usr/lib/python2.7/dist-packages/MAPICore.py", line 398, in SaveChanges
    return _MAPICore.IMAPIProp_SaveChanges(self, ulFlags)
MAPIErrorDiskError: MAPI error 80040116 (MAPI_E_DISK_ERROR)

And with very similar server log errors as with the imap transfer

Sun Jul 23 17:37:42 2017: [error  ] SQL [00003924] Failed: MySQL server has gone away, Query Size: 1081402, Query: "REPLACE INTO properties

SQL hasn’t gone away and there are no entries in the sql error.log.

I’ve bundled the BREAKS-KOPANO-2 export, the kopano-backup output and the server.log errors in an email to you. Hopefully this will help identify the cause of the problems i’m having because i think i’m out of options now.

G

fbartels

Hi @Galen ,

i’ve just tried to import you data to see if i’ll see the same error, but for me (running 8,4,0,1103) the restore succeeds.

From the kopano-backup output he stumbles over MAPI_E_DISK_ERROR, which is simply your “MySQL has gone away”.

I’ve asked a developer to look into the data to see if he can find something odd about it.

edit: are you using by any chance attachments stored in the database?

edit2: can you send in your server.cfg and mysql configuration in as well?

Galen

Thanks for testing the restore quickly @fbartels.

Did you test on Debian 9 with the default mariadb installed?

Attachments are saved as files.

Edit: server.cfg and mysql files sent.

edit2: These are probably useful -

# dpkg -l|grep kopano
ii  kopano-backup                    8.4.0~1074-4.1                         amd64        Utility to back up and restore Kopano stores
ii  kopano-client                    8.4.0~1074-4.1                         amd64        Kopano MAPI provider library
ii  kopano-common                    8.4.0~1074-4.1                         amd64        Shared files for Kopano Core services.
ii  kopano-contacts                  8.4.0~1074-4.1                         amd64        MAPI provider adding contact folders in the addressbook
ii  kopano-dagent                    8.4.0~1074-4.1                         amd64        E-Mail Delivery Agent for the Kopano Core
ii  kopano-gateway                   8.4.0~1074-4.1                         amd64        POP3 and IMAP Gateway for the Kopano Core
ii  kopano-ical                      8.4.0~1074-4.1                         amd64        ICal and CalDAV Gateway for Kopano Core
ii  kopano-lang                      8.4.0~1074-4.1                         all          Translations for Kopano Core components
ii  kopano-monitor                   8.4.0~1074-4.1                         amd64        Quota Monitor for Kopano Core
ii  kopano-presence                  8.4.0~1074-4.1                         amd64        kopano presence daemon
ii  kopano-search                    8.4.0~1074-4.1                         amd64        Indexed search engine for Kopano Core
ii  kopano-server                    8.4.0~1074-4.1                         amd64        Server component for Kopano Core
ii  kopano-server-packages           8.4.0~1074-4.1                         all          Metapackage to install the entire Kopano Core stack
ii  kopano-spooler                   8.4.0~1074-4.1                         amd64        E-mail Spooler for Kopano Core
ii  kopano-utils                     8.4.0~1074-4.1                         amd64        Admin command-line utils for Kopano Core
ii  kopano-webapp                    3.4.0.758-514.7                        all          New and improved WebApp for Kopano
ii  libgsoap-kopano-2-8-48           2.8.48-3.1                             amd64        Runtime libraries for gSOAP
ii  libvmime-kopano1                 0.9.2-12.1                             amd64        a C++ mail library (runtime library)
ii  python-kopano                    8.4.0~1074-4.1                         all          High-level Python bindings for Kopano

# dpkg -l|grep sql
ii  default-mysql-server             1.0.2                                  all          MySQL database server binaries and system database setup (metapackage)
ii  libaprutil1-dbd-sqlite3:amd64    1.5.4-3                                amd64        Apache Portable Runtime Utility Library - SQLite3 Driver
ii  libdbd-mysql-perl                4.041-2                                amd64        Perl5 database interface to the MariaDB/MySQL database
ii  libsqlite3-0:amd64               3.16.2-5                               amd64        SQLite 3 shared library
ii  mysql-common                     5.8+1.0.2                              all          MySQL database common files, e.g. /etc/mysql/my.cnf
ii  mysql-server                     5.5.9999+default                       amd64        MySQL database server binaries and system database setup [transitional]
ii  postfix-sqlite                   3.1.4-7                                amd64        SQLite map support for Postfix

Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 2
Server version: 10.1.23-MariaDB-9+deb9u1 Debian 9.0

Copyright (c) 2000, 2017, Oracle, MariaDB Corporation Ab and others.

G

fbartels

@Galen I personally tested on the latest ubuntu lts, but my college tried on debian 9 (not sure about his sql version, though). will forward the configuration to him.

fbartels

ok, so we’ve been toying around with this internally for a bit. One way we are able to trigger a similar error message is by reducing the innodb_log_file_size to 5mb, but with the mariadb version supplied in debian 9 it should actually default to 50mb.

apart from that your configuration pretty much looks like the default values, which is of course not good for performance either. I would therefore recommend to go through the suggestions at https://kb.kopano.io/display/WIKI/Tuning and then try again.

Galen

I’ve been testing this here with an fresh install of 16.04 LTS and with mysql 5.7 on Debian 9 instead of mariadb - both with default sql settings.

Both instances will restore the complete user set with only one warning thrown at the end of each user restore

backup - WARNING - skipping rule for unknown store/folder

I’m not sure what the skipped rule is as i can’t see any missing.

I’ll reload everything on Debian 9 afresh with mariadb and see if i can determine what the differences are.

Thanks for your assistance so far @fbartels

G

Galen

I can’t see anything between the mysql and mariadb settings that would break things. The innodb_log_file_size does default to 50M in maraiadb.

Pretty much everything that comes up in a search for the sql has gone away suggests that increasing max_allowed_packet or if timing out extend wait_timeout.

The log file time stamps show that there’s no waiting involved so it’s probably not that.

I’ve got these settings in mariadb at the moment and it still has errors with sql went way logged.

innodb_buffer_pool_dump_at_shutdown	OFF
innodb_buffer_pool_dump_now	OFF
innodb_buffer_pool_dump_pct	100
innodb_buffer_pool_filename	ib_buffer_pool
innodb_buffer_pool_instances	8
innodb_buffer_pool_load_abort	OFF
innodb_buffer_pool_load_at_startup	OFF
innodb_buffer_pool_load_now	OFF
innodb_buffer_pool_populate	OFF
innodb_buffer_pool_size	2147483648
innodb_lock_wait_timeout	50
innodb_log_arch_dir	./
innodb_log_arch_expire_sec	0
innodb_log_archive	OFF
innodb_log_block_size	512
innodb_log_buffer_size	33554432
innodb_log_checksum_algorithm	INNODB
innodb_log_compressed_pages	OFF
innodb_log_file_size	524288000
innodb_log_files_in_group	2
innodb_log_group_home_dir	./
lock_wait_timeout	31536000
max_allowed_packet	536870912
slave_max_allowed_packet	1073741824
wait_timeout	28800

Galen

The forum doesn’t like my previous post "Error

Post content was flagged as spam by Akismet.com"

G

fbartels

@Galen are you referring to another post than the one starting with “I can’t see anything between” because I can see this one even when i’m not logged in.

Galen

@fbartels The askimet spam error came up when i tried to edit the “I can’t see anything between” email. I tried to add “G” to the end but the spam message prohibit the edit

G

fbartels

@Galen hm… since askimet is now also blocking me from editing posts i have deactivated it again.