Closed osnet closed 3 years ago
hi @osnet
When I run the demo, kopano-search starts fine. So it would be great if you could provide some more details helping me with the debug.
BTW. If you want to start / stop / restart a service within the container it is best to use runit's sv
utility.
What might prevent kopano-search from starting is that it is sensetive to orphan pid files. That is why its runit file /etc/service/kopano-search/run
looks like this,
#!/bin/sh -e
exec 2>&1
rm -f /var/run/kopano/search.pid*
exec /usr/sbin/kopano-search -F
meh ... ok the deamon is installed, yes - my fault not to be exact enough the config is missing : )
While running the demo kopano-search starts and runs fine with default settings, that is without a cfg file. So, the fact that the cfg file is missing is by itself not likely the root cause of this problem.
You can see the current configuration by running
kopano-search --dump-config
It would be great if you could experiment with the settings to pinpoint what the actual issue is / was.
Many thanks for helping debugging this issue.
firing up the app and db:
[root@vsrv-mail-02 kopano]# make all
docker-compose stop
Stopping test_app_1 ... done
Stopping test_db_1 ... done
Stopping test_mta_1 ... done
docker-compose rm -f
Going to remove test_app_1, test_db_1, test_mta_1
Removing test_app_1 ... done
Removing test_db_1 ... done
Removing test_mta_1 ... done
docker-compose up -d
Creating test_mta_1 ... done
Creating test_db_1 ... done
Creating test_app_1 ... done
docker-compose logs -f
Attaching to test_app_1, test_mta_1, test_db_1
app_1 | Nov 3 18:49:41 docker-entrypoint.sh[1] NOTE: Setting syslogd level=5.
app_1 | Nov 3 18:49:42 docker-service.sh[29] NOTE: Setting up (syslogd) options () args (-nO- -l5 -S)
db_1 | 2020-11-03 18:49:38+01:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 1:10.5.6+maria~focal started.
db_1 | 2020-11-03 18:49:39+01:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
db_1 | 2020-11-03 18:49:39+01:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 1:10.5.6+maria~focal started.
db_1 | 2020-11-03 18:49:39 0 [Note] mysqld (mysqld 10.5.6-MariaDB-1:10.5.6+maria~focal) starting as process 1 ...
db_1 | 2020-11-03 18:49:39 0 [Note] InnoDB: Using Linux native AIO
db_1 | 2020-11-03 18:49:39 0 [Note] InnoDB: Uses event mutexes
db_1 | 2020-11-03 18:49:39 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
db_1 | 2020-11-03 18:49:39 0 [Note] InnoDB: Number of pools: 1
db_1 | 2020-11-03 18:49:39 0 [Note] InnoDB: Using SSE4.2 crc32 instructions
db_1 | 2020-11-03 18:49:39 0 [Note] mysqld: O_TMPFILE is not supported on /tmp (disabling future attempts)
db_1 | 2020-11-03 18:49:39 0 [Note] InnoDB: Initializing buffer pool, total size = 134217728, chunk size = 134217728
db_1 | 2020-11-03 18:49:39 0 [Note] InnoDB: Completed initialization of buffer pool
db_1 | 2020-11-03 18:49:39 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
db_1 | 2020-11-03 18:49:40 0 [Note] InnoDB: 128 rollback segments are active.
db_1 | 2020-11-03 18:49:40 0 [Note] InnoDB: Creating shared tablespace for temporary tables
db_1 | 2020-11-03 18:49:40 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
db_1 | 2020-11-03 18:49:40 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
db_1 | 2020-11-03 18:49:40 0 [Note] InnoDB: 10.5.6 started; log sequence number 374419102; transaction id 3253644
db_1 | 2020-11-03 18:49:40 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
mta_1 | Nov 3 18:49:38 docker-entrypoint.sh[1] NOTE: kopano.pwr-srv.net Alpine Linux v3.12 3.10.0-1127.13.1.el7.x86_64
mta_1 | postfix 3.5.7
mta_1 | dovecot 2.3.11.3
mta_1 | amavisd-new 2.12.0
mta_1 | spamassassin 3.4.4
mta_1 | clamav 0.102.4
mta_1 | Nov 3 18:49:38 docker-entrypoint.sh[1] NOTE: Configuring amavis for domains domain1.tld domain2.tld domain3.tld
mta_1 | Nov 3 18:49:39 docker-entrypoint.sh[1] NOTE: Setting dkim selector and domain to default and domain1.tld
mta_1 | Nov 3 18:49:39 docker-entrypoint.sh[1] WARN: Avoiding duplication: /etc/amavis/amavisd.conf @dkim_signature_options_bysender_maps = ( { "." => { ttl => 21*24*3600, c => "relaxed/simple" } } );
mta_1 | Nov 3 18:49:39 docker-entrypoint.sh[1] WARN: Avoiding duplication: /etc/amavis/amavisd.conf dkim_key("domain1.tld", "default", "/var/db/dkim/domain1.tld.default.privkey.pem");
mta_1 | Nov 3 18:49:39 docker-entrypoint.sh[1] NOTE: Changed owner to amavis for some files in /var/db/dkim
mta_1 | Nov 3 18:49:39 docker-entrypoint.sh[1] NOTE: Setting amavis parameter log_level = 5
mta_1 | Nov 3 18:49:39 docker-entrypoint.sh[1] NOTE: Setting amavis parameter sa_debug = 0
mta_1 | Nov 3 18:49:39 docker-entrypoint.sh[1] NOTE: Setting amavis parameter sa_tag_level_deflt = -999
mta_1 | Nov 3 18:49:39 docker-entrypoint.sh[1] NOTE: Discovering razor servers
db_1 | 2020-11-03 18:49:40 0 [Note] Plugin 'FEEDBACK' is disabled.
db_1 | 2020-11-03 18:49:40 0 [Note] Server socket created on IP: '::'.
db_1 | 2020-11-03 18:49:41 0 [Warning] 'proxies_priv' entry '@% root@d1d65e3647b9' ignored in --skip-name-resolve mode.
db_1 | 2020-11-03 18:49:42 0 [Note] mysqld: ready for connections.
db_1 | Version: '10.5.6-MariaDB-1:10.5.6+maria~focal' socket: '/run/mysqld/mysqld.sock' port: 3306 mariadb.org binary distribution
app_1 | Nov 3 18:49:45 kopano-server[75]: Starting kopano-server version 10.0.6 (pid 75 uid 0)
app_1 | Nov 3 18:49:45 kopano-dagent[73]: Starting kopano-dagent version 10.0.6 (pid 73 uid 0) (LMTP mode)
app_1 | Nov 3 18:49:45 kopano-spooler[77]: Starting kopano-spooler version 10.0.6 (pid 77 uid 0)
app_1 | Nov 3 18:49:45 kopano-spooler[77]: Starting kopano-spooler version 10.0.6 (pid 77 uid 999)
app_1 | Nov 3 18:49:45 kopano-dagent[73]: Starting kopano-dagent version 10.0.6 (pid 73 uid 999) (LMTP mode)
app_1 | 2020-11-03T18:49:45.431271: [warning] Gateway is started with bypass_auth=yes meaning username and password will not be checked.
app_1 | 2020-11-03T18:49:45.594755: [kopano-gateway|T71] [=======] Starting kopano-gateway version 10.0.6 (pid 71 uid 0)
app_1 | 2020-11-03T18:49:45.759929: [warning] Gateway is started with bypass_auth=yes meaning username and password will not be checked.
app_1 | 2020-11-03T18:49:45.762217: [kopano-gateway|T71] [=======] Starting kopano-gateway version 10.0.6 (pid 71 uid 999)
app_1 | Nov 3 18:49:45 kopano-spooler[77]: Logon to file:///var/run/kopano/server.sock: Remote side closed connection.
app_1 | Nov 3 18:49:45 kopano-spooler[77]: HrLogon server "default:" user "SYSTEM": network error
app_1 | Nov 3 18:49:45 kopano-spooler[77]: Unable to open admin session: network error (80040115)
app_1 | Nov 3 18:49:45 kopano-spooler[77]: Server connection lost. Reconnecting in 3 seconds...
db_1 | 2020-11-03 18:49:46 0 [Note] InnoDB: Buffer pool(s) load completed at 201103 18:49:45
mta_1 | Nov 3 18:49:47 docker-entrypoint.sh[1] NOTE: Updating spamassassin rules
mta_1 | Nov 3 18:49:47 docker-entrypoint.sh[1] NOTE: Setting up spamd-ham service
mta_1 | Nov 3 18:49:47 docker-service.sh[497] NOTE: Setting up (spamd-ham) options (name) args (/usr/local/bin/amavis-learn.sh /var/lib/kopano/spamd/ham:n)
mta_1 | Nov 3 18:49:47 docker-entrypoint.sh[1] NOTE: Setting up spamd-spam service
mta_1 | Nov 3 18:49:47 docker-service.sh[524] NOTE: Setting up (spamd-spam) options (name) args (/usr/local/bin/amavis-learn.sh /var/lib/kopano/spamd/spam:n)
mta_1 | Nov 3 18:49:48 docker-entrypoint.sh[1] NOTE: Setting syslogd level=5.
mta_1 | Nov 3 18:49:48 docker-service.sh[557] NOTE: Setting up (syslogd) options () args (-nO- -l5 -SDt)
mta_1 | Nov 3 18:49:48 docker-entrypoint.sh[1] NOTE: Configuring postfix for domains domain1.tld domain2.tld domain3.tld
mta_1 | Nov 3 18:49:48 docker-entrypoint.sh[1] WARN: Avoiding duplication: /etc/postfix/virt-domains domain1.tld #domain
mta_1 | Nov 3 18:49:48 docker-entrypoint.sh[1] WARN: Avoiding duplication: /etc/postfix/virt-domains domain2.tld #domain
mta_1 | Nov 3 18:49:48 docker-entrypoint.sh[1] WARN: Avoiding duplication: /etc/postfix/virt-domains domain3.tld #domain
app_1 | Nov 3 18:49:48 kopano-spooler[77]: Logon to file:///var/run/kopano/server.sock: Remote side closed connection.
app_1 | Nov 3 18:49:48 kopano-spooler[77]: HrLogon server "default:" user "SYSTEM": network error
app_1 | Nov 3 18:49:48 kopano-spooler[77]: Unable to open admin session: network error (80040115)
app_1 | Nov 3 18:49:51 kopano-spooler[77]: Logon to file:///var/run/kopano/server.sock: Remote side closed connection.
app_1 | Nov 3 18:49:51 kopano-spooler[77]: HrLogon server "default:" user "SYSTEM": network error
app_1 | Nov 3 18:49:51 kopano-spooler[77]: Unable to open admin session: network error (80040115)
mta_1 | Nov 3 18:49:53 docker-entrypoint.sh[1] NOTE: Setting postfix parameter message_size_limit = 52428800
app_1 | Nov 3 18:49:54 kopano-spooler[77]: Logon to file:///var/run/kopano/server.sock: Remote side closed connection.
app_1 | Nov 3 18:49:54 kopano-spooler[77]: HrLogon server "default:" user "SYSTEM": network error
app_1 | Nov 3 18:49:54 kopano-spooler[77]: Unable to open admin session: network error (80040115)
mta_1 | Nov 3 18:49:55 docker-entrypoint.sh[1] NOTE: Setting postfix parameter smtp_tls_security_level = none
mta_1 | Nov 3 18:49:57 docker-entrypoint.sh[1] NOTE: Setting postfix parameter smtp_tls_wrappermode = no
app_1 | Nov 3 18:49:57 kopano-spooler[77]: Logon to file:///var/run/kopano/server.sock: Remote side closed connection.
app_1 | Nov 3 18:49:57 kopano-spooler[77]: HrLogon server "default:" user "SYSTEM": network error
app_1 | Nov 3 18:49:57 kopano-spooler[77]: Unable to open admin session: network error (80040115)
mta_1 | Nov 3 18:49:59 docker-entrypoint.sh[1] NOTE: Setting postfix parameter virtual_transport = lmtp:app:2003
mta_1 | Nov 3 18:49:59 docker-entrypoint.sh[1] NOTE: Removing unlock file, locking the configuration.
app_1 | Nov 3 18:49:59 kopano-server[75]: Starting kopano-server version 10.0.6 (pid 75 uid 999)
app_1 | 2020-11-03T18:50:03.784498: [kopano-gateway|T105] [warning] Failed to open public store
app_1 | Nov 3 18:50:10 kopano-server[75]: Error while connecting to search on "file:///var/run/kopano/search.sock"
app_1 | Nov 3 18:50:10 kopano-server[75]: Error while connecting to search on "file:///var/run/kopano/search.sock"
app_1 | Nov 3 18:50:11 kopano-server[75]: Error while connecting to search on "file:///var/run/kopano/search.sock"
app_1 | Nov 3 18:50:11 kopano-server[75]: Error while connecting to search on "file:///var/run/kopano/search.sock"
[root@vsrv-mail-02 kopano]# docker exec -it test_app_1 bash
root@5471fe7f1779:/# kopano-search --dump-config
Usage: kopano-search [options]
kopano-search: error: no such option: --dump-config
root@5471fe7f1779:/# kopano-search -V
10.0.6
thats all ...
Hi @osnet
Many thanks for sharing this. It looks like kopano-search
does not start (which you already figured out) but it is not clear why.
It would be great if you could make sure that /etc/kopano/search.cfg
only contains
log_level = 5
and then restart the container and watch the log again with the hope that the reason for the start up difficulties will be revealed.
And despite most kopano commands, like kopano-server shows its configuration when issuing the option --dump-config
, kopano-search was not among them...
Other things to check is what the directory where kopano-search places its index files looks like (/var/lib/kopano/search/
).
haha
ehy master of the kopano dogger : )
log_level = 5
the search engine is running. : )
app_1 | 2020-11-04T10:38:41.861: [INFO ] index0 - syncing folder "Calendar" took 0.01 seconds (0 changes, 0 attachments)
app_1 | 2020-11-04T10:38:41.904: [INFO ] index0 - syncing folder: "D961311234C4415E8CAFBB189982E268" "Drafts"
app_1 | 2020-11-04T10:38:41.927: [INFO ] index0 - saved folder sync state: CF3A0100DF050000
app_1 | 2020-11-04T10:38:41.927: [INFO ] index0 - syncing folder "Drafts" took 0.02 seconds (0 changes, 0 attachments)
app_1 | 2020-11-04T10:38:41.965: [INFO ] index0 - syncing folder: "D961311234C4415E8CAFBB189982E268" "Conversation Action Settings"
app_1 | 2020-11-04T10:38:41.980: [INFO ] index0 - saved folder sync state: D03A0100E0050000
app_1 | 2020-11-04T10:38:41.981: [INFO ] index0 - syncing folder "Conversation Action Settings" took 0.01 seconds (0 changes, 0 attachments)
app_1 | Nov 4 10:38:42 kopano-server[73]: Error while connecting to search on "file:///var/run/kopano/search.sock"
app_1 | Nov 4 10:38:42 kopano-server[73]: Error while connecting to search on "file:///var/run/kopano/search.sock"
app_1 | 2020-11-04T10:38:42.017: [INFO ] index0 - syncing folder: "D961311234C4415E8CAFBB189982E268" "Deleted Items"
app_1 | 2020-11-04T10:38:42.035: [INFO ] index0 - saved folder sync state: D13A0100E1050000
app_1 | 2020-11-04T10:38:42.036: [INFO ] index0 - syncing folder "Deleted Items" took 0.02 seconds (0 changes, 0 attachments)
app_1 | 2020-11-04T10:38:42.072: [INFO ] index0 - syncing folder: "D961311234C4415E8CAFBB189982E268" "RSS Feeds
i guess you only have to wait til the search index has finished its job. after that the socket is available
Excellent.
This issue will be a good read for others studying the not totally streamlined startup sequence of the Kopano components.
Many thanks for sharing this.
Marking as wontfix
for clarity.
the construct is bothering me with msgs like
app_1 | Nov 1 22:09:00 kopano-server[76]: Error while connecting to search on "file:///var/run/kopano/search.sock"
to resolve this:
search.cfg
to app-confunfortunately the search deamon is not started on "boot" but available so this helps as workaraoud:
would be great to be build in