Kopano Archiver - "unable to complete"
-
A multi server setup with two servers:
mail01
is the main Mail server (mail01.sxps.test)mailarchiv01
is the Mail archive server (mailarchiv01.sxps.test)
root@mailarchiv01:/etc/kopano/sslkeys# kopano-stats --servers PR_EC_STATS_SERVER_NAME PR_EC_STATS_SERVER_HOST PR_EC_STATS_SERVER_HTTPPORT PR_EC_STATS_SERVER_SSLPORT PR_EC_STATS_SERVER_PROXYURL 0x67F6001E PR_EC_STATS_SERVER_HTTPSURL PR_EC_STATS_SERVER_FILEURL ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- mail01 mail01.sxps.test 236 237 http://mail01.sxps.test:236/ https://mail01.sxps.test:237/ file:///var/run/kopano/server.sock mailarchiv01 mailarchiv01.sxps.test 236 237 http://mailarchiv01.sxps.test:236/ https://mailarchiv01.sxps.test:237/file:///var/run/kopano/server.sock
The Test user:
root@mail01:/etc/kopano/ssl# kopano-admin --details "admin@sxps.test" Object id: 3 Extern id: wan-admin Username: admin@sxps.test Fullname: Emailaddress: admin@sxps.test Active: yes Administrator: yes Address book: Visible to current user Auto-accept meeting req:no Auto-process meeting req:no Home server: mail01 MDB provider: KOPANO_STORE_DELEGATE_GUID Store GUID: 38A3BF98C93C493199AF6536521B5621 Out Of Office: disabled Last logon: 10.06.2020 02:55:52 Last logoff: 10.06.2020 02:55:52 Server version: 10.0.3 Mapped properties: 0x8C6D0102 12 bytes PR_SURNAME Mc. Admin 0x3A58101E cos PR_EC_ENABLED_FEATURES imap; mobile; outlook; webapp PR_EC_DISABLED_FEATURES pop3 PR_EC_ARCHIVE_SERVERS mailarchiv01 Attached archives: 1 Root Folder in Archiv - (E32BD5C0A37D486B9C9F0A19C958A5C2) [Read Write] Current user store quota settings: Quota overrides: yes Warning level: 953.6M Soft level: 1.02G Hard level: 1.11G Current store size: 3.62M Groups (1): Everyone Archive details on node 'mailarchiv01': MDB provider: KOPANO_STORE_ARCHIVE_GUID Archive GUID: E32BD5C0A37D486B9C9F0A19C958A5C2 Current store size: 0,00 MiB
So, Multi Server setup seems fine, LDAP entries match, SSL Certificates are O.K. and the user has got an archive as you can see at the output from
kopano-admin --details "admin@sxps.test"
This is the output of the log file after running
kopano-archiver -A
:2020-06-10T03:01:08.922192: [info ] Startup command: "kopano-archiver" "-A" 2020-06-10T03:01:08.922213: [info ] Version 10.0.3 2020-06-10T03:01:08.922222: [crit ] Config settings: 2020-06-10T03:01:08.922228: [crit ] * archive_after = '90' 2020-06-10T03:01:08.922232: [crit ] * archive_enable = 'yes' 2020-06-10T03:01:08.922235: [crit ] * auto_attach_writable = 'yes' 2020-06-10T03:01:08.922239: [crit ] * cleanup_action = 'store' 2020-06-10T03:01:08.922253: [crit ] * cleanup_follow_purge_after = 'yes' 2020-06-10T03:01:08.922256: [crit ] * delete_after = '90' 2020-06-10T03:01:08.922259: [crit ] * delete_enable = 'yes' 2020-06-10T03:01:08.922263: [crit ] * delete_unread = 'no' 2020-06-10T03:01:08.922266: [crit ] * enable_auto_attach = 'yes' 2020-06-10T03:01:08.922269: [crit ] * log_buffer_size = '0' 2020-06-10T03:01:08.922272: [crit ] * log_file = '/var/log/kopano/archiver.log' 2020-06-10T03:01:08.922275: [crit ] * log_level = '6' 2020-06-10T03:01:08.922278: [crit ] * log_method = 'file' 2020-06-10T03:01:08.922281: [crit ] * log_timestamp = 'yes' 2020-06-10T03:01:08.922284: [crit ] * mysql_database = 'kopano_archiver' 2020-06-10T03:01:08.922288: [crit ] * mysql_engine = 'InnoDB' 2020-06-10T03:01:08.922297: [crit ] * mysql_host = 'localhost' 2020-06-10T03:01:08.922306: [crit ] * mysql_password = '********' 2020-06-10T03:01:08.922313: [crit ] * mysql_port = '3306' 2020-06-10T03:01:08.922319: [crit ] * mysql_socket = '' 2020-06-10T03:01:08.922323: [crit ] * mysql_user = 'kopano' 2020-06-10T03:01:08.922328: [crit ] * pid_file = '/var/run/kopano/archiver.pid' 2020-06-10T03:01:08.922335: [crit ] * purge-soft-deleted = 'no' 2020-06-10T03:01:08.922339: [crit ] * purge_after = '3650' 2020-06-10T03:01:08.922344: [crit ] * purge_enable = 'yes' 2020-06-10T03:01:08.922348: [crit ] * server_socket = 'https://mail01.sxps.test:237/kopano' 2020-06-10T03:01:08.922354: [crit ] * sslkey_file = '/etc/kopano/ssl/client.pem' 2020-06-10T03:01:08.922360: [crit ] * sslkey_pass = '********' 2020-06-10T03:01:08.922364: [crit ] * stub_after = '0' 2020-06-10T03:01:08.922367: [crit ] * stub_enable = 'no' 2020-06-10T03:01:08.922370: [crit ] * stub_unread = 'no' 2020-06-10T03:01:08.922373: [crit ] * track_history = 'no' 2020-06-10T03:01:08.922431: [debug ] Archiver mode: 6: (Archive) 2020-06-10T03:01:08.922435: [debug ] ArchiverImpl::GetControl() function entry 2020-06-10T03:01:08.922439: [debug ] ArchiverImpl::GetControl(): about to create an ArchiveControlImpl object 2020-06-10T03:01:08.922472: [debug ] Archiver action: archive all users (local only: no autoattach: no, flags 0) 2020-06-10T03:01:09.153690: [info ] User: on server "mail01" 2020-06-10T03:01:09.153716: [info ] User: SYSTEM on server "mail01" 2020-06-10T03:01:09.169400: [info ] Check server: "mail01" ssl="https://mail01.sxps.test:237/" flag=00000001 2020-06-10T03:01:09.170984: [debug ] Initializing provider "Kopano Directory Service" 2020-06-10T03:01:09.171021: [debug ] Initializing provider "Private Folders" 2020-06-10T03:01:09.171962: [debug ] Initializing provider "Public Folders" 2020-06-10T03:01:09.188154: [debug ] ArchiveStateUpdater::UpdateAll() function entry 2020-06-10T03:01:09.188177: [debug ] ArchiveStateUpdater::UpdateOne() function entry 2020-06-10T03:01:09.188181: [debug ] ArchiveStateUpdater::UpdateOne() about to call AddCouplingBased() 2020-06-10T03:01:09.188185: [debug ] Attaching coupling based archives. 2020-06-10T03:01:09.188188: [debug ] Empty coupling list 2020-06-10T03:01:09.188192: [debug ] ArchiveStateUpdater::UpdateOne() about to call AddServerBased() 2020-06-10T03:01:09.188195: [debug ] Attaching servername based archives. 2020-06-10T03:01:09.397805: [info ] User: on server "mail01" 2020-06-10T03:01:09.397843: [info ] User: SYSTEM on server "mail01" 2020-06-10T03:01:09.413173: [info ] Check server: "mail01" ssl="https://mail01.sxps.test:237/" flag=00000001 2020-06-10T03:01:09.414512: [debug ] Initializing provider "Kopano Directory Service" 2020-06-10T03:01:09.414530: [debug ] Initializing provider "Private Folders" 2020-06-10T03:01:09.415240: [debug ] Initializing provider "Public Folders" 2020-06-10T03:01:09.430816: [info ] Processing 0 users. 2020-06-10T03:01:09.430847: [debug ] Archiver result 0 (Success)
So - no Errors but it says “Processing 0 users” although we know there is at least the user “admin@sxps.test”.
When I try to execute the archiving of the user directly with
kopano-archiver -u admin@sxps.test -A
, this is the output of the log file:2020-06-10T03:03:52.651889: [info ] Startup command: "kopano-archiver" "-u" "admin@sxps.test" "-A" 2020-06-10T03:03:52.651911: [info ] Version 10.0.3 2020-06-10T03:03:52.651920: [crit ] Config settings: 2020-06-10T03:03:52.651927: [crit ] * archive_after = '90' 2020-06-10T03:03:52.651930: [crit ] * archive_enable = 'yes' 2020-06-10T03:03:52.651934: [crit ] * auto_attach_writable = 'yes' 2020-06-10T03:03:52.651937: [crit ] * cleanup_action = 'store' 2020-06-10T03:03:52.651940: [crit ] * cleanup_follow_purge_after = 'yes' 2020-06-10T03:03:52.651943: [crit ] * delete_after = '90' 2020-06-10T03:03:52.651946: [crit ] * delete_enable = 'yes' 2020-06-10T03:03:52.651950: [crit ] * delete_unread = 'no' 2020-06-10T03:03:52.651953: [crit ] * enable_auto_attach = 'yes' 2020-06-10T03:03:52.651956: [crit ] * log_buffer_size = '0' 2020-06-10T03:03:52.651959: [crit ] * log_file = '/var/log/kopano/archiver.log' 2020-06-10T03:03:52.651962: [crit ] * log_level = '6' 2020-06-10T03:03:52.651965: [crit ] * log_method = 'file' 2020-06-10T03:03:52.651968: [crit ] * log_timestamp = 'yes' 2020-06-10T03:03:52.651972: [crit ] * mysql_database = 'kopano_archiver' 2020-06-10T03:03:52.651975: [crit ] * mysql_engine = 'InnoDB' 2020-06-10T03:03:52.651978: [crit ] * mysql_host = 'localhost' 2020-06-10T03:03:52.651981: [crit ] * mysql_password = '********' 2020-06-10T03:03:52.651984: [crit ] * mysql_port = '3306' 2020-06-10T03:03:52.651987: [crit ] * mysql_socket = '' 2020-06-10T03:03:52.651991: [crit ] * mysql_user = 'kopano' 2020-06-10T03:03:52.651994: [crit ] * pid_file = '/var/run/kopano/archiver.pid' 2020-06-10T03:03:52.651997: [crit ] * purge-soft-deleted = 'no' 2020-06-10T03:03:52.652000: [crit ] * purge_after = '3650' 2020-06-10T03:03:52.652003: [crit ] * purge_enable = 'yes' 2020-06-10T03:03:52.652006: [crit ] * server_socket = 'https://mail01.sxps.test:237/kopano' 2020-06-10T03:03:52.652010: [crit ] * sslkey_file = '/etc/kopano/ssl/client.pem' 2020-06-10T03:03:52.652013: [crit ] * sslkey_pass = '********' 2020-06-10T03:03:52.652016: [crit ] * stub_after = '0' 2020-06-10T03:03:52.652019: [crit ] * stub_enable = 'no' 2020-06-10T03:03:52.652022: [crit ] * stub_unread = 'no' 2020-06-10T03:03:52.652025: [crit ] * track_history = 'no' 2020-06-10T03:03:52.652090: [debug ] Archiver mode: 6: (Archive) 2020-06-10T03:03:52.652095: [debug ] ArchiverImpl::GetControl() function entry 2020-06-10T03:03:52.652099: [debug ] ArchiverImpl::GetControl(): about to create an ArchiveControlImpl object 2020-06-10T03:03:52.652134: [debug ] Archiver action: archive user "admin@sxps.test" (autoattach: no, flags 0) 2020-06-10T03:03:52.652140: [debug ] ArchiveControlImpl::Archive(): function entry. 2020-06-10T03:03:52.652150: [debug ] ArchiveControlImpl::Archive(): about to create collector. 2020-06-10T03:03:52.652157: [debug ] ArchiveControlImpl::Archive(): about to get updater. 2020-06-10T03:03:52.890144: [info ] User: on server "mail01" 2020-06-10T03:03:52.890195: [info ] User: SYSTEM on server "mail01" 2020-06-10T03:03:52.905895: [info ] Check server: "mail01" ssl="https://mail01.sxps.test:237/" flag=00000001 2020-06-10T03:03:52.907342: [debug ] Initializing provider "Kopano Directory Service" 2020-06-10T03:03:52.907365: [debug ] Initializing provider "Private Folders" 2020-06-10T03:03:52.908258: [debug ] Initializing provider "Public Folders" 2020-06-10T03:03:52.924852: [debug ] For "admin@sxps.test": ArchiveControlImpl::Archive(): about to update store of user "admin@sxps.test". Flags: 0x00000002 2020-06-10T03:03:52.924874: [debug ] ArchiveStateUpdater::Update(): function entry 2020-06-10T03:03:52.924881: [debug ] ArchiveStateUpdater::Update(): about to call UpdateOne() 2020-06-10T03:03:52.924885: [debug ] ArchiveStateUpdater::UpdateOne() function entry 2020-06-10T03:03:52.924888: [debug ] ArchiveStateUpdater::UpdateOne() about to call AddCouplingBased() 2020-06-10T03:03:52.924901: [debug ] Attaching coupling based archives. 2020-06-10T03:03:52.924904: [debug ] Empty coupling list 2020-06-10T03:03:52.924907: [debug ] ArchiveStateUpdater::UpdateOne() about to call AddServerBased() 2020-06-10T03:03:52.924911: [debug ] Attaching servername based archives. 2020-06-10T03:03:53.330175: [debug ] ArchiveControlImpl::Archive() at exit. Return code before transformation: unable to complete (80040400) 2020-06-10T03:03:53.330207: [debug ] Archiver result 1 (Failure)
As you can see, it fails. But why? Eventually I missed something in the config file?
root@mailarchiv01:/etc/kopano/sslkeys# cat /etc/kopano/archiver.cfg # See the kopano-archiver.cfg(5) manpage for details and more directives # Server Unix socket location server_socket = https://mail01.sxps.test:237/kopano # Login to the storage server using this SSL Key sslkey_file = /etc/kopano/ssl/client.pem # The password of the SSL Key sslkey_pass = admin # server_socket = file:///var/run/kopano/server.sock #log_method = auto # Loglevel (0(none), 1(crit), 2(err), 3(warn), 4(notice), 5(info), 6(debug)) log_level = 6 log_file = /var/log/kopano/archiver.log log_timestamp = yes # MySQL hostname to connect to for database access mysql_host = localhost # MySQL port to connect with (usually 3306) mysql_port = 3306 # The user under which we connect with MySQL mysql_user = kopano # The password for the user (leave empty for no password) mysql_password = j235jki213LkMns74F4a99KnjwU # Override the default MySQL socket to access mysql locally # Works only if the mysql_host value is empty or 'localhost' #mysql_socket = # Database to connect to mysql_database = kopano_archiver # Specify whether on each archive run an auto-attach run is performed in order # to match the attached archives to the requested state as specified in LDAP or # ADS. # Default: no enable_auto_attach = yes # Specify whether an auto attached archive will be granted write permissions # for the user it's attached to. # Default: yes auto_attach_writable = yes # Disable archiving momentarily by setting this to 'no' archive_enable = yes # Archive messages older than N days archive_after = 90 # Stubbing messages requires a multi-server environment stub_enable = no # Only stub messages after N days, 0 for the same as archive_after #stub_after = 0 # Delete archives messages from the original server. Only archived messages can be deleted. delete_enable = yes # Also delete unread messages from the original server #delete_unread = no # Only delete messages after N days, 0 for the same as archive_after delete_after = 90 # Purge messages from the archive server(s). purge_enable = yes # Only purge messages after N days, 0 for the same as archive_after # Default: 2555 (~7 years) purge_after = 3650 cleanup_follow_purge_after = yes
-
Form completion, this is the user server entry in LDAP:
{ "dn": "cn=mail01, ou=servers, dc=sxps, dc=test", "objectclass": [ "device", "ipHost", "kopano-server", "top" ], "cn": "mail01", "iphostnumber": "mail01.sxps.test", "kopanocontainspublic": "1", "kopanofilepath": "/var/run/kopano/server.sock", "kopanohttpport": "236", "kopanosslport": "237" }
The archiv server entry in LDAP:
{ "dn": "cn=mailarchiv01, ou=servers, dc=sxps, dc=test", "objectclass": [ "device", "ipHost", "kopano-server", "top" ], "cn": "mailarchiv01", "iphostnumber": "mailarchiv01.sxps.test", "kopanocontainspublic": "1", "kopanofilepath": "/var/run/kopano/server.sock", "kopanohttpport": "236", "kopanosslport": "237" }
And the user entry in LDAP:
{ "dn": "cn=admin, dc=sxps, dc=test", "objectclass": [ "posixAccount", "top", "kopano-user", "inetOrgPerson", "user" ], "gidnumber": "wan-admin", "homedirectory": "/home/wan-admin", "mail": "admin@sxps.test", "uidnumber": "wan-admin", "kopanoaliases": [ "admin2@sxps.test" ], "kopanoaccount": "1", "kopanoadmin": "1", "sn": "Mc. Admin", "cn": "admin@sxps.test", "entryuuid": "wan-admin", "uid": "wan-admin", "o": "cos", "kopanoquotaoverride": "1", "kopanoenabledfeatures": "imap", "kopanodisabledfeatures": "pop3", "kopanoquotawarn": "1000000000", "kopanoquotasoft": "1100000000", "kopanoquotahard": "1200000000", "kopanouserserver": "mail01", "kopanouserarchiveservers": "mailarchiv01", }
-
@birduser I’m no LDAP expert but I’d check in the schema if an FQDN is allowed in ‘iphostnumber’ instead of an IP address. Also check ‘uidnumber’ and ‘gidnumber’ where you have text instead of an integer.
-
I tried again, and started with a fresh openLDAP server, this is the LDIF file of the user:
dn: uid=john,ou=people,dc=sxps,dc=test objectClass: posixAccount objectClass: top objectClass: kopano-user objectClass: inetOrgPerson gidNumber: 1000 cn: John Doe homeDirectory: /home/john mail: john@sxps.test uidNumber: 1000 kopanoAliases: johnDoe@sxps.test kopanoUserServer: mail01 kopanoUserArchiveServers: mailarchiv01 uid: john kopanoAccount: 1 kopanoAdmin: 1 sn: Doe userPassword: john kopanoQuotaOverride: 1 kopanoEnabledFeatures: imap kopanoDisabledFeatures: pop3 o: cos kopanoQuotaWarn: 1000000000 kopanoQuotaSoft: 1100000000 kopanoQuotaHard: 1200000000
The LDIF File of the Server folder:
dn: ou=servers,dc=sxps,dc=test objectClass: organizationalUnit objectClass: top ou: servers
The LDIF File of the Mail Server
dn: cn=mail01,ou=servers,dc=sxps,dc=test objectClass: device objectClass: ipHost objectClass: kopano-server objectClass: top cn: mail01 ipHostNumber: mail01.sxps.test kopanocontainspublic: 1 kopanofilepath: /var/run/kopano/server.sock kopanohttpport: 236 kopanosslport: 237
The LDIF File of the Mail Archive Server
dn: cn=mailarchiv01,ou=servers,dc=sxps,dc=test objectClass: device objectClass: ipHost objectClass: kopano-server objectClass: top cn: mailarchiv01 ipHostNumber: mailarchiv01.sxps.test kopanocontainspublic: 1 kopanofilepath: /var/run/kopano/server.sock kopanohttpport: 236 kopanosslport: 237
As Patrick mentioned using an IP in “iphostnumber” results in an SSL error, so there definitely has to be the host name.
I can login with the user, I can see the mails and it even got a mail Archive:
root@mail01:~# kopano-admin --details "John Doe" Object id: 4 Extern id: john Username: John Doe Fullname: Emailaddress: john@sxps.it Active: yes Administrator: yes Address book: Visible to current user Auto-accept meeting req:no Auto-process meeting req:no Home server: mail01 MDB provider: KOPANO_STORE_DELEGATE_GUID Store GUID: 5C4BFA864AC1430397AD4185FC35E2FC Out Of Office: disabled Last logon: 17.06.2020 20:42:50 Last logoff: 17.06.2020 20:42:50 Server version: 10.0.3 Mapped properties: 0x8C6D0102 48 bytes PR_SURNAME Doe 0x3A58101E cos PR_EC_ENABLED_FEATURES imap; mobile; outlook; webapp PR_EC_DISABLED_FEATURES pop3 PR_EC_ARCHIVE_SERVERS mailarchiv01 Attached archives: 1 in Failed id=0000000038A1BB1005E5101AA1BB08002B2A56C200007A617261666136636C69656E742E646C6C0000000000247E257CA2CE4640BAA08790EDDEDD0501000000010000002583E51B33294A7389F3025A97DEB04770736575646F3A2F2F6D61696C617263686976303100: failoneprovider (0x8004011D) () [Modified: missing or invalid] Current user store quota settings: Quota overrides: yes Warning level: 953.6M Soft level: 1.02G Hard level: 1.11G Current store size: 5.59M Groups (1): Everyone Archive details on node 'mailarchiv01': Unable to access node 'mailarchiv01': success(0x80040115)
But it still fails with the same error.
What is thisUnable to access node 'mailarchiv01': success(0x80040115)
, unable but success? Is there the problem?This is the Archiver log:
2020-06-17T20:40:02.852614: [info ] Startup command: "kopano-archiver" "-u" "John Doe" "-A" 2020-06-17T20:40:02.839142: [debug ] Initializing provider "Kopano Directory Service" 2020-06-17T20:40:02.839179: [debug ] Initializing provider "Private Folders" 2020-06-17T20:40:02.840766: [debug ] Initializing provider "Public Folders" 2020-06-17T20:40:02.852614: [info ] Startup command: "kopano-archiver" "-u" "John Doe" "-A" 2020-06-17T20:40:02.852639: [info ] Version 10.0.3 2020-06-17T20:40:02.852650: [crit ] Config settings: 2020-06-17T20:40:02.852656: [crit ] * archive_after = '90' 2020-06-17T20:40:02.852660: [crit ] * archive_enable = 'yes' 2020-06-17T20:40:02.852663: [crit ] * auto_attach_writable = 'yes' 2020-06-17T20:40:02.852667: [crit ] * cleanup_action = 'store' 2020-06-17T20:40:02.852670: [crit ] * cleanup_follow_purge_after = 'yes' 2020-06-17T20:40:02.852674: [crit ] * delete_after = '90' 2020-06-17T20:40:02.852677: [crit ] * delete_enable = 'yes' 2020-06-17T20:40:02.852681: [crit ] * delete_unread = 'no' 2020-06-17T20:40:02.852684: [crit ] * enable_auto_attach = 'yes' 2020-06-17T20:40:02.852687: [crit ] * log_buffer_size = '0' 2020-06-17T20:40:02.852691: [crit ] * log_file = '/var/log/kopano/archiver.log' 2020-06-17T20:40:02.852700: [crit ] * log_level = '6' 2020-06-17T20:40:02.852713: [crit ] * log_method = 'file' 2020-06-17T20:40:02.852722: [crit ] * log_timestamp = 'yes' 2020-06-17T20:40:02.852730: [crit ] * mysql_database = 'kopano_archiver' 2020-06-17T20:40:02.852736: [crit ] * mysql_engine = 'InnoDB' 2020-06-17T20:40:02.852742: [crit ] * mysql_host = 'localhost' 2020-06-17T20:40:02.852747: [crit ] * mysql_password = '********' 2020-06-17T20:40:02.852750: [crit ] * mysql_port = '3306' 2020-06-17T20:40:02.852754: [crit ] * mysql_socket = '' 2020-06-17T20:40:02.852757: [crit ] * mysql_user = 'kopano' 2020-06-17T20:40:02.852760: [crit ] * pid_file = '/var/run/kopano/archiver.pid' 2020-06-17T20:40:02.852764: [crit ] * purge-soft-deleted = 'no' 2020-06-17T20:40:02.852767: [crit ] * purge_after = '3650' 2020-06-17T20:40:02.852771: [crit ] * purge_enable = 'yes' 2020-06-17T20:40:02.852774: [crit ] * server_socket = 'https://mail01.sxps.test:237/kopano' 2020-06-17T20:40:02.852778: [crit ] * sslkey_file = '/etc/kopano/ssl/client.pem' 2020-06-17T20:40:02.852781: [crit ] * sslkey_pass = '********' 2020-06-17T20:40:02.852784: [crit ] * stub_after = '0' 2020-06-17T20:40:02.852788: [crit ] * stub_enable = 'no' 2020-06-17T20:40:02.852791: [crit ] * stub_unread = 'no' 2020-06-17T20:40:02.852794: [crit ] * track_history = 'no' 2020-06-17T20:40:02.852864: [debug ] Archiver mode: 6: (Archive) 2020-06-17T20:40:02.852869: [debug ] ArchiverImpl::GetControl() function entry 2020-06-17T20:40:02.852874: [debug ] ArchiverImpl::GetControl(): about to create an ArchiveControlImpl object 2020-06-17T20:40:02.852923: [debug ] Archiver action: archive user "John Doe" (autoattach: no, flags 0) 2020-06-17T20:40:02.852932: [debug ] ArchiveControlImpl::Archive(): function entry. 2020-06-17T20:40:02.852948: [debug ] ArchiveControlImpl::Archive(): about to create collector. 2020-06-17T20:40:02.852955: [debug ] ArchiveControlImpl::Archive(): about to get updater. 2020-06-17T20:40:02.885800: [info ] User: on server "mail01" 2020-06-17T20:40:02.885828: [info ] User: SYSTEM on server "mail01" 2020-06-17T20:40:02.897479: [info ] Check server: "mail01" ssl="https://mail01.sxps.test:237/" flag=00000001 2020-06-17T20:40:02.899176: [debug ] Initializing provider "Kopano Directory Service" 2020-06-17T20:40:02.899214: [debug ] Initializing provider "Private Folders" 2020-06-17T20:40:02.900437: [debug ] Initializing provider "Public Folders" 2020-06-17T20:40:02.911717: [debug ] For "John Doe": ArchiveControlImpl::Archive(): about to update store of user "John Doe". Flags: 0x00000002 2020-06-17T20:40:02.911741: [debug ] ArchiveStateUpdater::Update(): function entry 2020-06-17T20:40:02.911748: [debug ] ArchiveStateUpdater::Update(): about to call UpdateOne() 2020-06-17T20:40:02.911752: [debug ] ArchiveStateUpdater::UpdateOne() function entry 2020-06-17T20:40:02.911755: [debug ] ArchiveStateUpdater::UpdateOne() about to call AddCouplingBased() 2020-06-17T20:40:02.911759: [debug ] Attaching coupling based archives. 2020-06-17T20:40:02.911762: [debug ] Empty coupling list 2020-06-17T20:40:02.911765: [debug ] ArchiveStateUpdater::UpdateOne() about to call AddServerBased() 2020-06-17T20:40:02.911768: [debug ] Attaching servername based archives. 2020-06-17T20:40:02.947653: [debug ] ArchiveControlImpl::Archive() at exit. Return code before transformation: unable to complete (80040400) 2020-06-17T20:40:02.947678: [debug ] Archiver result 1 (Failure)
The mail server has in mail.log:
Jun 18 00:25:14 mailarchiv01 kopano-server[4761]: Starting kopano-server version 10.0.3 (pid 4761 uid 0) Jun 18 00:25:14 mailarchiv01 kopano-server[4761]: Starting kopano-server version 10.0.3 (pid 4761 uid 998) Jun 18 00:25:15 mailarchiv01 kopano-spooler[434]: Table reload requested, breaking server connection Jun 18 00:25:15 mailarchiv01 kopano-spooler[434]: Server connection lost. Reconnecting in 3 seconds... Jun 18 00:25:32 mailarchiv01 kopano-server[4761]: K-1538: Unable to get company details for object id 1: public store server
and the archiver server has in mail.log:
Jun 18 00:29:43 mail01 kopano-server[1273]: Server shutdown complete. Jun 18 00:29:43 mail01 kopano-server[4834]: Starting kopano-server version 10.0.3 (pid 4834 uid 0) Jun 18 00:29:43 mail01 kopano-server[4834]: Starting kopano-server version 10.0.3 (pid 4834 uid 998) Jun 18 00:29:44 mail01 kopano-spooler[441]: Table reload requested, breaking server connection Jun 18 00:29:44 mail01 kopano-spooler[441]: Server connection lost. Reconnecting in 3 seconds... Jun 18 00:29:54 mail01 kopano-server[4834]: K-1538: Unable to get company details for object id 1: public store server Jun 18 00:29:55 mail01 kopano-server[4834]: K-1538: Unable to get company details for object id 1: public store server
No errors except of this
K-1538: Unable to get company details for object id 1: public store server
but I could not find anything about this.I am out of ideas and really need another entry point to find the cause of the error.
My guess is, the communication between the servers does not work properly, how can I test this?
As this is a test environment, external mail delivery does not work at the moment, but the archiving process should work anyways, right?
Any Ideas?
-
Hi @birduser,
I would recommend to get in contact with the Kopano support so that they can have a look at your setup.
-
Okay, I gave it another shot.
I started with a fresh Debian 10 installation with Kopano running as single server instance connected to an openLDAP Server to sync the users.
Everything is working fine, Users are syncing, no errors in logs and I can login with the LDAP user “John Doe” in the Webapproot@mail01:~# kopano-cli --list-users User list for Default (2): User Full Name Homeserver ---------------------------------------------------------- John Doe Unknown SYSTEM SYSTEM Unknown
Now going through the steps of:
https://documentation.kopano.io/kopanocore_administrator_manual/special_kc_configurations.html#running-kc-components-beyond-localhostAnd everything works on both servers, no errors in the logs this time, NOTHING, all commands like
kopano-cli --list-users
work like a charm on both servers.Now installing Archiver on the Archive Server and the Archive of the user is beeing created, as you cal see:
root@mailarchiv01:/tmp# kopano-admin --details "John Doe" Object id: 3 Extern id: john Username: John Doe Fullname: Emailaddress: john@sxps.it Active: yes Administrator: yes Address book: Visible to current user Auto-accept meeting req:no Auto-process meeting req:no Home server: mail01 MDB provider: KOPANO_STORE_DELEGATE_GUID Store GUID: 048A43E0A223432FA4FD1FCBB4F940F0 Out Of Office: disabled Last logon: 18.06.2020 22:01:23 Last logoff: 18.06.2020 22:01:23 Server version: 10.0.3 Mapped properties: 0x8C6D0102 48 bytes PR_SURNAME Doe 0x3A58101E cos PR_EC_ENABLED_FEATURES imap; mobile; outlook; webapp PR_EC_DISABLED_FEATURES pop3 PR_EC_ARCHIVE_SERVERS mailarchiv01 Attached archives: 1 Root Folder in Archiv - (EC00488518994E93A0D1E155EBEE4DAE) [Read Write] Current user store quota settings: Quota overrides: yes Warning level: 953.6M Soft level: 1.02G Hard level: 1.11G Current store size: 4.52M Groups (1): Everyone Archive details on node 'mailarchiv01': MDB provider: KOPANO_STORE_ARCHIVE_GUID Archive GUID: EC00488518994E93A0D1E155EBEE4DAE Current store size: 0,00 MiB
But still the same error in the logs:
2020-06-18T21:46:57.920336: [info ] Startup command: "kopano-archiver" "-u" "John Doe" "-A" 2020-06-18T21:46:57.920359: [info ] Version 10.0.3 2020-06-18T21:46:57.920367: [crit ] Config settings: 2020-06-18T21:46:57.920373: [crit ] * archive_after = '90' 2020-06-18T21:46:57.920377: [crit ] * archive_enable = 'yes' 2020-06-18T21:46:57.920381: [crit ] * auto_attach_writable = 'yes' 2020-06-18T21:46:57.920384: [crit ] * cleanup_action = 'store' 2020-06-18T21:46:57.920387: [crit ] * cleanup_follow_purge_after = 'yes' 2020-06-18T21:46:57.920391: [crit ] * delete_after = '90' 2020-06-18T21:46:57.920394: [crit ] * delete_enable = 'yes' 2020-06-18T21:46:57.920398: [crit ] * delete_unread = 'no' 2020-06-18T21:46:57.920401: [crit ] * enable_auto_attach = 'yes' 2020-06-18T21:46:57.920405: [crit ] * log_buffer_size = '0' 2020-06-18T21:46:57.920408: [crit ] * log_file = '/var/log/kopano/archiver.log' 2020-06-18T21:46:57.920411: [crit ] * log_level = '6' 2020-06-18T21:46:57.920415: [crit ] * log_method = 'file' 2020-06-18T21:46:57.920418: [crit ] * log_timestamp = 'yes' 2020-06-18T21:46:57.920421: [crit ] * mysql_database = 'kopano_archiver' 2020-06-18T21:46:57.920425: [crit ] * mysql_engine = 'InnoDB' 2020-06-18T21:46:57.920428: [crit ] * mysql_host = 'localhost' 2020-06-18T21:46:57.920431: [crit ] * mysql_password = '********' 2020-06-18T21:46:57.920435: [crit ] * mysql_port = '3306' 2020-06-18T21:46:57.920438: [crit ] * mysql_socket = '' 2020-06-18T21:46:57.920441: [crit ] * mysql_user = 'kopano' 2020-06-18T21:46:57.920445: [crit ] * pid_file = '/var/run/kopano/archiver.pid' 2020-06-18T21:46:57.920448: [crit ] * purge-soft-deleted = 'no' 2020-06-18T21:46:57.920451: [crit ] * purge_after = '3650' 2020-06-18T21:46:57.920455: [crit ] * purge_enable = 'yes' 2020-06-18T21:46:57.920458: [crit ] * server_socket = 'https://mail01.sxps.it:237/kopano' 2020-06-18T21:46:57.920461: [crit ] * sslkey_file = '/etc/kopano/ssl/client.pem' 2020-06-18T21:46:57.920465: [crit ] * sslkey_pass = '********' 2020-06-18T21:46:57.920468: [crit ] * stub_after = '0' 2020-06-18T21:46:57.920471: [crit ] * stub_enable = 'no' 2020-06-18T21:46:57.920485: [crit ] * stub_unread = 'no' 2020-06-18T21:46:57.920488: [crit ] * track_history = 'no' 2020-06-18T21:46:57.920554: [debug ] Archiver mode: 6: (Archive) 2020-06-18T21:46:57.920559: [debug ] ArchiverImpl::GetControl() function entry 2020-06-18T21:46:57.920562: [debug ] ArchiverImpl::GetControl(): about to create an ArchiveControlImpl object 2020-06-18T21:46:57.920603: [debug ] Archiver action: archive user "John Doe" (autoattach: no, flags 0) 2020-06-18T21:46:57.920607: [debug ] ArchiveControlImpl::Archive(): function entry. 2020-06-18T21:46:57.920619: [debug ] ArchiveControlImpl::Archive(): about to create collector. 2020-06-18T21:46:57.920628: [debug ] ArchiveControlImpl::Archive(): about to get updater. 2020-06-18T21:46:57.948598: [info ] User: on server "mail01" 2020-06-18T21:46:57.948624: [info ] User: SYSTEM on server "mail01" 2020-06-18T21:46:57.958005: [info ] Check server: "mail01" ssl="https://mail01.sxps.it:237/" flag=00000003 2020-06-18T21:46:57.959482: [debug ] Initializing provider "Kopano Directory Service" 2020-06-18T21:46:57.959501: [debug ] Initializing provider "Private Folders" 2020-06-18T21:46:57.960537: [debug ] Initializing provider "Public Folders" 2020-06-18T21:46:57.960851: [debug ] Received a redirect from file:///var/run/kopano/server.sock to https://mail01.sxps.it:237/ for public store 2020-06-18T21:46:57.979699: [debug ] For "John Doe": ArchiveControlImpl::Archive(): about to update store of user "John Doe". Flags: 0x00000002 2020-06-18T21:46:57.979722: [debug ] ArchiveStateUpdater::Update(): function entry 2020-06-18T21:46:57.979728: [debug ] ArchiveStateUpdater::Update(): about to call UpdateOne() 2020-06-18T21:46:57.979732: [debug ] ArchiveStateUpdater::UpdateOne() function entry 2020-06-18T21:46:57.979735: [debug ] ArchiveStateUpdater::UpdateOne() about to call AddCouplingBased() 2020-06-18T21:46:57.979738: [debug ] Attaching coupling based archives. 2020-06-18T21:46:57.979741: [debug ] Empty coupling list 2020-06-18T21:46:57.979744: [debug ] ArchiveStateUpdater::UpdateOne() about to call AddServerBased() 2020-06-18T21:46:57.979747: [debug ] Attaching servername based archives. 2020-06-18T21:46:58.051465: [debug ] ArchiveControlImpl::Archive() at exit. Return code before transformation: unable to complete (80040400) 2020-06-18T21:46:58.051490: [debug ] Archiver result 1 (Failure)
That cannot be too much, I mean everything works, EVERYTHING, except of the archiver, who creates an archive for the user but then fails every time with
unable to complete
Where is the error here? I just need a little hint, please!
I even would contact Kopano Support like @fbartels mentioned, but you write here “If you do not have a paid Kopano subscription we’re not leaving you out in the cold. Check out the documentation, our knowledge base or ask your question on the forum!”
I do not have a paid Kopano subscription, checked the documentation and this is why I am asking here :)
-
Okay, I got some news.
All the time I installed the archiver on the mail archive server kopano instance and it failed with the message mentioned above.
This time, I installed the archiver on the main mail server, used the same /etc/kopano/archiver.cfg file like before and BAM - it worked, as you can see here:root@mail01:~# kopano-admin --details "John Doe" Object id: 4 Extern id: john Username: John Doe Fullname: Emailaddress: john@sxps.it Active: yes Administrator: yes Address book: Visible to current user Auto-accept meeting req:no Auto-process meeting req:no Home server: mail01 MDB provider: KOPANO_STORE_DELEGATE_GUID Store GUID: 048A43E0A223432FA4FD1FCBB4F940F0 Out Of Office: disabled Last logon: 19.06.2020 02:05:36 Last logoff: 19.06.2020 02:05:36 Server version: 10.0.3 Mapped properties: 0x8C6D0102 48 bytes PR_SURNAME Doe 0x3A58101E cos PR_EC_ENABLED_FEATURES imap; mobile; outlook; webapp PR_EC_DISABLED_FEATURES pop3 PR_EC_ARCHIVE_SERVERS mailarchiv01 Attached archives: 1 Root Folder in Archiv - (EC00488518994E93A0D1E155EBEE4DAE) [Read Write] Current user store quota settings: Quota overrides: yes Warning level: 953.6M Soft level: 1.02G Hard level: 1.11G Current store size: 147K Groups (1): Everyone Archive details on node 'mailarchiv01': MDB provider: KOPANO_STORE_ARCHIVE_GUID Archive GUID: EC00488518994E93A0D1E155EBEE4DAE Current store size: 4,39 MiB root@mail01:~#
When I login into the webApp I can see the archived mails in the Archive Mailbox. Perfect!
Starting the archiver for user John Doe now gives:
2020-06-19T02:18:01.968937: [info ] Startup command: "kopano-archiver" "-u" "John Doe" "-A" 2020-06-19T02:18:01.968958: [info ] Version 10.0.3 2020-06-19T02:18:01.968967: [crit ] Config settings: 2020-06-19T02:18:01.968973: [crit ] * archive_after = '90' 2020-06-19T02:18:01.968977: [crit ] * archive_enable = 'yes' 2020-06-19T02:18:01.968980: [crit ] * auto_attach_writable = 'yes' 2020-06-19T02:18:01.968984: [crit ] * cleanup_action = 'store' 2020-06-19T02:18:01.968987: [crit ] * cleanup_follow_purge_after = 'yes' 2020-06-19T02:18:01.968991: [crit ] * delete_after = '90' 2020-06-19T02:18:01.968994: [crit ] * delete_enable = 'yes' 2020-06-19T02:18:01.968998: [crit ] * delete_unread = 'no' 2020-06-19T02:18:01.969001: [crit ] * enable_auto_attach = 'yes' 2020-06-19T02:18:01.969005: [crit ] * log_buffer_size = '0' 2020-06-19T02:18:01.969008: [crit ] * log_file = '/var/log/kopano/archiver.log' 2020-06-19T02:18:01.969012: [crit ] * log_level = '6' 2020-06-19T02:18:01.969015: [crit ] * log_method = 'file' 2020-06-19T02:18:01.969032: [crit ] * log_timestamp = 'yes' 2020-06-19T02:18:01.969035: [crit ] * mysql_database = 'kopano_archiver' 2020-06-19T02:18:01.969039: [crit ] * mysql_engine = 'InnoDB' 2020-06-19T02:18:01.969042: [crit ] * mysql_host = 'localhost' 2020-06-19T02:18:01.969049: [crit ] * mysql_password = '********' 2020-06-19T02:18:01.969052: [crit ] * mysql_port = '3306' 2020-06-19T02:18:01.969056: [crit ] * mysql_socket = '' 2020-06-19T02:18:01.969059: [crit ] * mysql_user = 'kopano' 2020-06-19T02:18:01.969063: [crit ] * pid_file = '/var/run/kopano/archiver.pid' 2020-06-19T02:18:01.969066: [crit ] * purge-soft-deleted = 'no' 2020-06-19T02:18:01.969070: [crit ] * purge_after = '3650' 2020-06-19T02:18:01.969073: [crit ] * purge_enable = 'yes' 2020-06-19T02:18:01.969077: [crit ] * server_socket = 'https://mail01.sxps.it:237/kopano' 2020-06-19T02:18:01.969093: [crit ] * sslkey_file = '/etc/kopano/ssl/client.pem' 2020-06-19T02:18:01.969097: [crit ] * sslkey_pass = '********' 2020-06-19T02:18:01.969100: [crit ] * stub_after = '0' 2020-06-19T02:18:01.969104: [crit ] * stub_enable = 'no' 2020-06-19T02:18:01.969107: [crit ] * stub_unread = 'no' 2020-06-19T02:18:01.969111: [crit ] * track_history = 'no' 2020-06-19T02:18:01.969192: [debug ] Archiver mode: 6: (Archive) 2020-06-19T02:18:01.969197: [debug ] ArchiverImpl::GetControl() function entry 2020-06-19T02:18:01.969201: [debug ] ArchiverImpl::GetControl(): about to create an ArchiveControlImpl object 2020-06-19T02:18:01.969236: [debug ] Archiver action: archive user "John Doe" (autoattach: no, flags 0) 2020-06-19T02:18:01.969241: [debug ] ArchiveControlImpl::Archive(): function entry. 2020-06-19T02:18:01.969251: [debug ] ArchiveControlImpl::Archive(): about to create collector. 2020-06-19T02:18:01.969266: [debug ] ArchiveControlImpl::Archive(): about to get updater. 2020-06-19T02:18:02.016894: [info ] User: on server "mail01" 2020-06-19T02:18:02.017134: [info ] User: SYSTEM on server "mail01" 2020-06-19T02:18:02.025013: [info ] Check server: "mail01" ssl="https://mail01.sxps.it:237/" flag=00000003 2020-06-19T02:18:02.026338: [debug ] Initializing provider "Kopano Directory Service" 2020-06-19T02:18:02.026353: [debug ] Initializing provider "Private Folders" 2020-06-19T02:18:02.027171: [debug ] Initializing provider "Public Folders" 2020-06-19T02:18:02.036421: [debug ] For "John Doe": ArchiveControlImpl::Archive(): about to update store of user "John Doe". Flags: 0x00000002 2020-06-19T02:18:02.036443: [debug ] ArchiveStateUpdater::Update(): function entry 2020-06-19T02:18:02.036450: [debug ] ArchiveStateUpdater::Update(): about to call UpdateOne() 2020-06-19T02:18:02.036454: [debug ] ArchiveStateUpdater::UpdateOne() function entry 2020-06-19T02:18:02.036458: [debug ] ArchiveStateUpdater::UpdateOne() about to call VerifyAndUpdate() 2020-06-19T02:18:02.045697: [debug ] Removing implicitly attached archives. 2020-06-19T02:18:02.049974: [debug ] Attaching coupling based archives. 2020-06-19T02:18:02.049996: [debug ] Empty coupling list 2020-06-19T02:18:02.050000: [debug ] Attaching servername based archives. 2020-06-19T02:18:02.050004: [debug ] Empty servername list 2020-06-19T02:18:02.050014: [debug ] ArchiveControlImpl::Archive(): about to do real archive run. 2020-06-19T02:18:02.050021: [info ] For "John Doe": Archiving store for user "John Doe" 2020-06-19T02:18:02.065551: [info ] Archiving messages 2020-06-19T02:18:02.066583: [info ] For "John Doe": Processing batch of 0 messages 2020-06-19T02:18:02.066596: [info ] Done processing batch 2020-06-19T02:18:02.066773: [info ] Done archiving messages 2020-06-19T02:18:02.066780: [info ] Deleting old messages 2020-06-19T02:18:02.067637: [info ] For "John Doe": Processing batch of 0 messages 2020-06-19T02:18:02.067648: [info ] Done processing batch 2020-06-19T02:18:02.067950: [info ] Done deleting messages 2020-06-19T02:18:02.067959: [info ] Purging archive(s) 2020-06-19T02:18:02.082961: [info ] For "John Doe": Purging 0 messaged from archive folder 2020-06-19T02:18:02.086982: [info ] For "John Doe" in folder "Posteingang": Purging 0 messaged from archive folder 2020-06-19T02:18:02.088658: [info ] Done purging archive(s) 2020-06-19T02:18:02.089374: [debug ] ArchiveControlImpl::Archive() at exit. Return code before transformation: success (0) 2020-06-19T02:18:02.089390: [debug ] Archiver result 0 (Success)
Success! Yeaaaa!
But still, the documentation here says: “The Kopano Archiver packages can be installed on any node in a multi-server setup. However, installing the packages on the archive node is recommended.”
Why does it work on my main node, but not - like recommended - on my archive node?
-
@birduser said in Kopano Archiver - "unable to complete":
I even would contact Kopano Support like @fbartels mentioned, but you write here
Yes, but imho if you have an environment that can benefit from the archiver, then you should also have the budget to buy a Kopano subscription.
-
Hi @fbartels
Its not about the budget.At this moment I don’t even know if Kopano meets all my requirements, and this is why I am testing it. I think you wouldn’t buy a car either without making a test ride, and you would never pay the owner of the car for fixing problems before the test ride is done.
You announce your software as “100% Open source”, and this it the reason why I gave Kopano a try. What exactly is the sense in making a software open source, and announcing on the site that “we’re not leaving you out in the cold” when the only response from the community is: “Buy a subscription”, even AFTER I came this far by my own - the Archiver is now working BUT not on the archive node.
Who tells me, that i did not run into another bug, this is not the first I run into see here
I would have been willing to buy a subscription at the end to prevent future problems and support your software, if I know everything works the way it should, but the way you rudely pushed my in this direction without giving me any advice, thats not the way I want to be threated as a - maybe future - customer.
-
@birduser said in Kopano Archiver - "unable to complete":
when the only response from the community is: “Buy a subscription”
Well you have been helped here before, haven’t you?
In any case you are free to ignore my recommendations.