dagent 8.7.80.355 Unable to commit message: disk error (80040116) => Mailbox temporarily unavailable



  • Hi,

    i have problems wit “Mailbox temporarily unavailable”-messages from postfix.

    I think this problems came from dagents troubles with special utf-8 input, most mails are ok, a few are still in the mailqueue and all of them have charset: utf-8

    dagent.log

    Sun Jan  6 07:09:50 2019: [info   ] LMTP thread exiting
    Sun Jan  6 07:09:50 2019: [debug  ] Initializing provider "Kopano Directory Service"
    Sun Jan  6 07:09:50 2019: [debug  ] Initializing provider "Private Folders"
    Sun Jan  6 07:09:50 2019: [debug  ] Initializing provider "Public Folders"
    Sun Jan  6 07:09:50 2019: [info   ] Mail will be delivered in Inbox
    Sun Jan  6 07:09:50 2019: [debug  ] Trying to parse alternative multipart 1 of mail body
    Sun Jan  6 07:09:50 2019: [debug  ] HTML4 meta tag found: charset="text/html; charset=utf-8"
    Sun Jan  6 07:09:50 2019: [debug  ] HTML charset adjusted to "utf-8"
    Sun Jan  6 07:09:50 2019: [debug  ] renovate_encoding: reading data using charset "utf-8" succeeded.
    Sun Jan  6 07:09:50 2019: [info   ] * Loading plugins started
    Sun Jan  6 07:09:50 2019: [info   ] ** Checking plugins in /var/lib/kopano/dagent/plugins
    Sun Jan  6 07:09:50 2019: [info   ] * Loading plugins done
    Sun Jan  6 07:09:50 2019: [debug  ] Initializing provider "Kopano Directory Service"
    Sun Jan  6 07:09:50 2019: [debug  ] Initializing provider "Private Folders"
    Sun Jan  6 07:09:50 2019: [debug  ] Initializing provider "Public Folders"
    Sun Jan  6 07:09:50 2019: [info   ] * PostConverting processing started
    Sun Jan  6 07:09:50 2019: [info   ] * PostConverting processing done
    Sun Jan  6 07:09:50 2019: [info   ] * PreDelivery processing started
    Sun Jan  6 07:09:50 2019: [info   ] * PreDelivery processing done
    Sun Jan  6 07:09:50 2019: [debug  ] Initializing provider "Kopano Directory Service"
    Sun Jan  6 07:09:50 2019: [debug  ] Initializing provider "Private Folders"
    Sun Jan  6 07:09:50 2019: [debug  ] Initializing provider "Public Folders"
    Sun Jan  6 07:09:50 2019: [debug  ] Initializing provider "Kopano Directory Service"
    Sun Jan  6 07:09:50 2019: [debug  ] Initializing provider "Private Folders"
    Sun Jan  6 07:09:50 2019: [debug  ] Initializing provider "Public Folders"
    Sun Jan  6 07:09:50 2019: [info   ] * PreRuleProcess processing started
    Sun Jan  6 07:09:50 2019: [info   ] * PreRuleProcess processing done
    Sun Jan  6 07:09:50 2019: [debug  ] Target user has OOF inactive
    Sun Jan  6 07:09:50 2019: [info   ] Mail will be delivered in Inbox
    Sun Jan  6 07:09:50 2019: [error  ] Unable to commit message: disk error (80040116)
    Sun Jan  6 07:09:50 2019: [error  ] Unable to deliver message to "spass": disk error (80040116)
    Sun Jan  6 07:09:50 2019: [error  ] Unable to deliver all messages for server "default:"
    Sun Jan  6 07:09:50 2019: [info   ] Finished processing message
    Sun Jan  6 07:09:50 2019: [debug  ] < 450 4.2.0 ulrike.spass@wvs-heidelberg.de Mailbox temporarily unavailable
    
    
    


  • possibility to grep “unavailable” in dagent.log, loglevel debug in dagent.cfg:

    grep  Mailbox temporarily unavailable /var/log/kopano/dagent.log |less
    

  • Kopano

    That command won’t work, but that is besides the point:

    # grep  Mailbox temporarily unavailable /var/log/kopano/dagent.log
    grep: temporarily: No such file or directory
    grep: unavailable: No such file or directory
    

    you will want to check the logging of kopano-server what it is logging when the dagent is encountering the disk error. As with the imap topic, its probably best for reproduction to have such a mail.



  • @fbartels said in dagent 8.7.80.355 Unable to commit message: disk error (80040116) => Mailbox temporarily unavailable:

    That command won’t work, but that is besides the point:

    You are right, but it works if /var/log/kopano/dagent.log exists, but command is wrong, you’re right. :)
    should be enough:

    grep Mailbox /var/log/kopano/dagent.log 
    

    I have those mails, but they have nearly 100k in ugly html, should i post it here? Will spam this thread.

    I check the server.log, thanks.
    Your’re working on sunday?



  • part of server.log

     Jan  6 18:24:51 2019: [error  ] SQL [00000005] Failed: Incorrect string value: '\xF0\x9F\x91\x8D\x0D\x0A...' for column 'val_string' at row 32, Qu
    ery Size: 32023, 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(3540598,34257,30,null,'\"Sun, 6 Jan 2019 17:08:28 +0100\" \"Fwd: Doodle: Ci
    sco: IT-Essentials
    


  • Perhaps a Problem with utf8 and 4 Bytes?
    https://stackoverflow.com/questions/10957238/incorrect-string-value-when-trying-to-insert-utf-8-into-mysql-via-jdbc

    MySQL with Kopano:

    MariaDB [(none)]> SHOW VARIABLES LIKE  'char%';
    +--------------------------+----------------------------+
    | Variable_name            | Value                      |
    +--------------------------+----------------------------+
    | character_set_client     | utf8mb4                    |
    | character_set_connection | utf8mb4                    |
    | character_set_database   | utf8mb4                    |
    | character_set_filesystem | binary                     |
    | character_set_results    | utf8mb4                    |
    | character_set_server     | utf8mb4                    |
    | character_set_system     | utf8                       |
    | character_sets_dir       | /usr/share/mysql/charsets/ |
    +--------------------------+----------------------------+
    8 rows in set (0.00 sec)
    


  • @fbartels

    Hi Felix

    I can confirm the same errors on some mails in dagent and kopano-core and mysql logs with Kopano 8.7 beta on UCS4.3

    rg

    Christian


  • Kopano

    Thanks for the report @externa1. are you able to provide an eml of a mail causing this?



  • @fbartels

    Hi Felix - you can download 2 examples from the link:

    https://remote.ckc-it.at/nextcloud/index.php/s/yKBdkpb95xMfq65

    rg
    Christian


  • Kopano

    Thanks @externa1. I have created https://jira.kopano.io/browse/KC-1376 to reproduce this and further look into this.


  • Kopano

    @externa1 @irrlicht I managed to reproduce this issue on a local machine that was upgraded from the current final. For 8.7 we introduced support of utf8mb4 to allow additional characters (see https://jira.kopano.io/browse/KC-725).

    Since that database conversion can take some time, we afterwards decided to decouple this from the server start. There is still one remaining pr (not yet merged because of test failures) that will address issues like yours above, when the conversion was not yet run.

    The long term “fix” is to run kopano-dbadm usmp (when kopano-server is not running) to convert your database.

    PS: small details to add here: if you create a new database this will of course be created with support for utf8mb4. its just old databases that need to be updated.



  • kopano-dbadm usmp
    

    Thank you Felix,

    solution works, mails are delivered - most of them spam :)

    For reading “sleeping” mails in mailq from postfix there’s the tool “pfqueue” in the debian repository. It’s easier than postqueue- and postsuper-magic



  • @fbartels

    Hi Felix,

    yes that fixed my problem - all mails in postfix queue could be delivered now

    rg
    Christian



  • i had the same problem.
    kopano-dbadm usmp fixed that problem :)

    thanks felix



  • @fbartels I had the same problem as well and kopano-dbadm usmp fixed it. However, when running the command I got the following error

    Wed Jan  9 22:20:36 2019: [error  ] 0x556b9f65af88: SQL Failed: All parts of a PRIMARY KEY must be NOT NULL; if you need NULL in a key, use UNIQUE instead, Query: "ALTER TABLE `objectproperty` MODIFY COLUMN `propname` varchar(185) CHARACTER SET utf8mb4 BINARY DEFAULT NULL"
    Wed Jan  9 22:20:36 2019: [error  ] KDatabase::I_Update() query failed: "All parts of a PRIMARY KEY must be NOT NULL; if you need NULL in a key, use UNIQUE instead", query: ALTER TABLE `objectproperty` MODIFY COLUMN `propname` varchar(185) CHARACTER SET utf8mb4 BINARY DEFAULT NULL
    Wed Jan  9 22:20:36 2019: [error  ] dbadm: action failed: disk error (80000007)
    
    


  • This post is deleted!


  • Hello all, I had the same issue and could solve delivery problem with kopano-dbadm usmp!
    Thanks a lot, I thought this could be a database nightmare, luckily it was a quick job.

    But unfortunately I got the same error like @aurel - so I’m wondering what kind of future “behavior” I might notice :-/

    kopano-dbadm usmp
    Sun Jan 13 16:45:19 2019: [notice ] dbadm: executing action "usmp-column-shrink"
    Sun Jan 13 16:45:19 2019: [notice ] usmp: discovering overly long named properties...
    Sun Jan 13 16:45:19 2019: [notice ] usmp: purging long namedprops from "properties"...
    Sun Jan 13 16:45:19 2019: [notice ] usmp: expunged 0 rows
    Sun Jan 13 16:45:19 2019: [notice ] usmp: purging long namedprops from "tproperties"...
    Sun Jan 13 16:45:19 2019: [notice ] usmp: expunged 0 rows
    Sun Jan 13 16:45:19 2019: [notice ] usmp: purging long namedprops from "mvproperties"...
    Sun Jan 13 16:45:19 2019: [notice ] usmp: expunged 0 rows
    Sun Jan 13 16:45:19 2019: [notice ] usmp: purging long namedprops from "indexedproperties"...
    Sun Jan 13 16:45:19 2019: [notice ] usmp: expunged 0 rows
    Sun Jan 13 16:45:19 2019: [notice ] usmp: purging long namedprops from "singleinstances"...
    Sun Jan 13 16:45:19 2019: [notice ] usmp: expunged 0 rows
    Sun Jan 13 16:45:19 2019: [notice ] usmp: purging long namedprops from "lob"...
    Sun Jan 13 16:45:19 2019: [notice ] usmp: expunged 0 rows
    Sun Jan 13 16:45:19 2019: [notice ] usmp: resizing names.namestring...
    Sun Jan 13 16:45:19 2019: [notice ] usmp: resizing receivefolder.messageclass...
    Sun Jan 13 16:45:20 2019: [notice ] usmp: resizing objectproperty.propname...
    Sun Jan 13 16:45:20 2019: [notice ] usmp: resizing objectmvproperty.propname...
    Sun Jan 13 16:45:20 2019: [notice ] usmp: resizing settings.name...
    Sun Jan 13 16:45:20 2019: [notice ] dbadm: executing action "usmp-charset"
    Sun Jan 13 16:45:20 2019: [notice ] usmp: converting "abchanges" to utf8mb4...
    Sun Jan 13 16:45:20 2019: [notice ] usmp: converting "acl" to utf8mb4...
    Sun Jan 13 16:45:20 2019: [notice ] usmp: converting "changes" to utf8mb4...
    Sun Jan 13 16:45:20 2019: [notice ] usmp: converting "deferredupdate" to utf8mb4...
    Sun Jan 13 16:45:20 2019: [notice ] usmp: converting "hierarchy" to utf8mb4...
    Sun Jan 13 16:45:20 2019: [notice ] usmp: converting "indexedproperties" to utf8mb4...
    Sun Jan 13 16:45:20 2019: [notice ] usmp: converting "lob" to utf8mb4...
    Sun Jan 13 16:45:20 2019: [notice ] usmp: converting "mvproperties" to utf8mb4...
    Sun Jan 13 16:45:20 2019: [notice ] usmp: converting "object" to utf8mb4...
    Sun Jan 13 16:45:20 2019: [notice ] usmp: converting "objectrelation" to utf8mb4...
    Sun Jan 13 16:45:20 2019: [notice ] usmp: converting "outgoingqueue" to utf8mb4...
    Sun Jan 13 16:45:20 2019: [notice ] usmp: converting "properties" to utf8mb4...
    Sun Jan 13 16:46:58 2019: [notice ] usmp: converting "receivefolder" to utf8mb4...
    Sun Jan 13 16:46:58 2019: [notice ] usmp: converting "searchresults" to utf8mb4...
    Sun Jan 13 16:46:58 2019: [notice ] usmp: converting "settings" to utf8mb4...
    Sun Jan 13 16:46:58 2019: [notice ] usmp: converting "singleinstances" to utf8mb4...
    Sun Jan 13 16:47:00 2019: [notice ] usmp: converting "stores" to utf8mb4...
    Sun Jan 13 16:47:00 2019: [notice ] usmp: converting "syncedmessages" to utf8mb4...
    Sun Jan 13 16:47:00 2019: [notice ] usmp: converting "syncs" to utf8mb4...
    Sun Jan 13 16:47:00 2019: [notice ] usmp: converting "tproperties" to utf8mb4...
    Sun Jan 13 16:49:33 2019: [notice ] usmp: converting "users" to utf8mb4...
    Sun Jan 13 16:49:33 2019: [notice ] usmp: converting "versions" to utf8mb4...
    Sun Jan 13 16:49:33 2019: [notice ] usmp: converting "objectproperty" to utf8mb4...
    Sun Jan 13 16:49:33 2019: [error  ] 0x55e62988ef88: SQL Failed: All parts of a PRIMARY KEY must be NOT NULL; if you need NULL in a key, use UNIQUE instead, Query: "ALTER TABLE `objectproperty` MODIFY COLUMN `propname` varchar(185) CHARACTER SET utf8mb4 BINARY DEFAULT NULL"
    Sun Jan 13 16:49:33 2019: [error  ] KDatabase::I_Update() query failed: "All parts of a PRIMARY KEY must be NOT NULL; if you need NULL in a key, use UNIQUE instead", query: ALTER TABLE `objectproperty` MODIFY COLUMN `propname` varchar(185) CHARACTER SET utf8mb4 BINARY DEFAULT NULL
    Sun Jan 13 16:49:33 2019: [error  ] dbadm: action failed: disk error (80000007)
    

    maybe it is because I use this database since a long time? > 8 years

    +-------+-------+-------+----------+------------------+---------------------+
    | major | minor | micro | revision | databaserevision | updatetime          |
    +-------+-------+-------+----------+------------------+---------------------+
    |     6 |    30 |     0 |    20002 |               29 | 2010-07-27 17:11:02 |
    

    If I can support for further analyses, export things or whatever - please let me know

    Cheers!
    DaveJ



  • I have the same problem, for now I’ve rollback everything.
    To my last working version 8.7.80.424.3b35b58f3-0+49.1


  • Kopano

    @avalon which same problem? the “unable to commit” message or the sql error when running kopano-dbadm?



  • @fbartels After try to update with “kopano-dbadm usmp” I have the following issue:

    Mon Jan 14 17:54:24 2019: [notice ] usmp: converting "versions" to utf8mb4...
    Mon Jan 14 17:54:24 2019: [notice ] usmp: converting "objectproperty" to utf8mb4...
    Mon Jan 14 17:54:24 2019: [error  ] 0x55697c529f90: SQL Failed: All parts of a PRIMARY KEY must be NOT NULL; if you need NULL in a key, use UNIQUE instead, Query: "ALTER TABLE `objectproperty` MODIFY COLUMN `propname` varchar(185) CHARACTER SET utf8mb4 BINARY DEFAULT NULL"
    Mon Jan 14 17:54:24 2019: [error  ] KDatabase::I_Update() query failed: "All parts of a PRIMARY KEY must be NOT NULL; if you need NULL in a key, use UNIQUE instead", query: ALTER TABLE `objectproperty` MODIFY COLUMN `propname` varchar(185) CHARACTER SET utf8mb4 BINARY DEFAULT NULL
    Mon Jan 14 17:54:24 2019: [error  ] dbadm: action failed: disk error (80000007)
    
    

    And no one can sign up anymore.


Log in to reply