Nextcloud-snap: failed to set datadir to /var/snap/nextcloud/8971/mysql/

Created on 8 Oct 2018  ·  11Comments  ·  Source: nextcloud/nextcloud-snap

After rebooting for a kernel update my nextcloud service will not come back up. I am unable to connect via web browser. Everything had been working fine for months. The main error seems to be in the mysql component

Oct 07 22:52:44 lithium nextcloud.mysql[944]: 2018-10-07T21:52:43.804787Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
Oct 07 22:52:44 lithium nextcloud.mysql[944]: 2018-10-07T21:52:44.166170Z 0 [ERROR] --initialize specified but the data directory has files in it. Aborting.
Oct 07 22:52:44 lithium nextcloud.mysql[944]: 2018-10-07T21:52:44.166285Z 0 [ERROR] Aborting
Oct 07 22:52:45 lithium nextcloud.mysql[944]: Starting MySQL
Oct 07 22:52:46 lithium mysqld_safe[2053]: Starting mysqld daemon with databases from /var/snap/nextcloud/8971/mysql
Oct 07 22:52:47 lithium mysqld[2058]: /snap/nextcloud/8971/bin/mysqld (mysqld 5.7.22-log) starting as process 2058 ...
Oct 07 22:52:47 lithium audit[2058]: SECCOMP auid=4294967295 uid=0 gid=0 ses=4294967295 subj==snap.nextcloud.mysql (enforce) pid=2058 comm="mysqld" exe="/snap/nextcloud/8971/bin/mysqld" sig=0 arch=c000003e syscall=116 compat=0 ip=0x7f425a712f09 code=0x50000
Oct 07 22:52:47 lithium kernel: audit: type=1326 audit(1538949167.156:27): auid=4294967295 uid=0 gid=0 ses=4294967295 subj==snap.nextcloud.mysql (enforce) pid=2058 comm="mysqld" exe="/snap/nextcloud/8971/bin/mysqld" sig=0 arch=c000003e syscall=116 compat=0 ip=0x7f425a712f09 code=0x50000
Oct 07 22:52:47 lithium mysqld[2058]: failed to set datadir to /var/snap/nextcloud/8971/mysql/
Oct 07 22:52:47 lithium mysqld[2058]: /snap/nextcloud/8971/bin/mysqld: Shutdown complete
Oct 07 22:52:48 lithium nextcloud.mysql[944]: ... * The server quit without updating PID file (/tmp/pids/mysql.pid).

There were some errors from apache during the shutdown before this, but I am not sure if they are related

Oct 07 22:50:50 lithium nextcloud.apache[9967]: error: cannot communicate with server: Post http://localhost/v2/snapctl: read unix @->/run/snapd-snap.socket: read: conn
ection reset by peer
Oct 07 22:50:50 lithium nextcloud.apache[9967]: error: cannot communicate with server: Post http://localhost/v2/snapctl: write unix @->/run/snapd-snap.socket: write: br
oken pipe
Oct 07 22:50:50 lithium nextcloud.mysql[9955]: Shutting down MySQL
Oct 07 22:50:50 lithium nextcloud.apache[9967]: error: cannot communicate with server: Post http://localhost/v2/snapctl: EOF
Oct 07 22:50:50 lithium nextcloud.apache[9967]: error: cannot communicate with server: Post http://localhost/v2/snapctl: write unix @->/run/snapd-snap.socket: write: broken pipe
Oct 07 22:50:50 lithium nextcloud.apache[9967]: error: cannot communicate with server: Post http://localhost/v2/snapctl: EOF
Oct 07 22:50:50 lithium nextcloud.apache[9967]: error: cannot communicate with server: Post http://localhost/v2/snapctl: EOF
Oct 07 22:50:51 lithium nextcloud.apache[9967]: AH00558: httpd: Could not reliably determine the server's fully qualified domain name, using 127.0.1.1. Set the 'ServerName' directive globally to suppress this message
Oct 07 22:50:51 lithium systemd[1]: Stopped Service for snap application nextcloud.apache.
Oct 07 22:50:53 lithium nextcloud.mysql[9955]: ... *
Oct 07 22:50:53 lithium systemd[1]: Stopped Service for snap application nextcloud.mysql.

I am running 13.0.6snap1 from the 13/stable channel. Kernel update was from 4.17.17-1~bpo9+1 to 4.18.6-1~bpo9+1 (Debian backports). I am on debian 9.5 on amd64.

I have tried disabling and re enabling. I have tried refreshing the snap. I have tried rolling back the kernel. I have tried rebooting the machine.

Let me know what further info you need. Thanks.

picture samtygier

Most helpful comment

I think I have found a solution. I also had mysql installed outside the snap. If I remove that and restart the snap

sudo apt remove mysql-common
sudo snap restart nextcloud

So I wonder if the snap is mistakingly launching the external mysql instead of the internal one?

picture samtygier on 10 Oct 2018
👍4

All 11 comments

I also have this issue. Also running the Debian 9 series. I also turned over every stone I could think of, but I am also getting this error. Happy to see it isn't just me.

lakerssuperman picture lakerssuperman on 8 Oct 2018

in /var/log/mysql/error.log I see the error

2018-10-08T21:18:08.226024Z mysqld_safe Starting mysqld daemon with databases from /var/snap/nextcloud/8971/mysql
mysqld: Can't change dir to '/var/snap/nextcloud/8971/mysql/' (Errcode: 13 - Permission denied)
2018-10-08T21:18:08.641994Z 0 [Warning] Ignoring user change to 'root' because the user was set to 'mysql' earlier on the command line
samtygier picture samtygier on 8 Oct 2018

I'm on Debian, run for a few months and getting the same error after restarting for a kernel update. This is a qemu instance on 4.9.0-8 kernel.
Here are the debug logs:
`


Apache

Status

● snap.nextcloud.apache.service - Service for snap application nextcloud.apache
   Loaded: loaded (/etc/systemd/system/snap.nextcloud.apache.service; enabled; vendor preset: enabled)
   Active: active (running) since Tue 2018-10-09 21:24:22 UTC; 10min ago
  Process: 3907 ExecStop=/usr/bin/snap run --command=stop nextcloud.apache (code=exited, status=0/SUCCESS)
 Main PID: 5168 (run-httpd)
    Tasks: 3 (limit: 4915)
   Memory: 620.0K
      CPU: 1.396s
   CGroup: /system.slice/snap.nextcloud.apache.service
           ├─5168 /bin/sh /snap/nextcloud/9077/bin/run-httpd -k start -DFOREGROUND
           ├─5242 /bin/sh /snap/nextcloud/9077/bin/setup_nextcloud
           └─8046 sleep 1

Oct 09 21:24:22 ny01.mysite.com systemd[1]: Started Service for snap application nextcloud.apache.
Oct 09 21:24:22 ny01.mysite.com /usr/bin/snap[5168]: cmd.go:105: DEBUG: restarting into "/snap/core/current/usr/bin/snap"
Oct 09 21:24:23 ny01.mysite.com nextcloud.apache[5168]: Making sure nextcloud is setup...

Journal

-- Logs begin at Tue 2018-10-09 21:15:02 UTC, end at Tue 2018-10-09 21:34:40 UTC. --
Oct 09 21:15:05 ny01.mysite.com /usr/bin/snap[636]: cmd.go:105: DEBUG: restarting into "/snap/core/current/usr/bin/snap"
Oct 09 21:15:04 ny01.mysite.com systemd[1]: Started Service for snap application nextcloud.apache.
Oct 09 21:15:09 ny01.mysite.com nextcloud.apache[636]: Making sure nextcloud is setup...
Oct 09 21:20:10 ny01.mysite.com systemd[1]: Stopping Service for snap application nextcloud.apache...
Oct 09 21:20:10 ny01.mysite.com /usr/bin/snap[3907]: cmd.go:105: DEBUG: restarting into "/snap/core/current/usr/bin/snap"
Oct 09 21:20:11 ny01.mysite.com nextcloud.apache[3907]: No certificates are active: using HTTP only
Oct 09 21:20:11 ny01.mysite.com nextcloud.apache[3907]: AH00558: httpd: Could not reliably determine the server's fully qualified domain name, using ny01.mysite.com. Set the 'ServerName' directive globally to suppress this message
Oct 09 21:20:11 ny01.mysite.com nextcloud.apache[3907]: httpd (no pid file) not running
Oct 09 21:20:11 ny01.mysite.com nextcloud.apache[636]: Waiting for PHP...
Oct 09 21:20:11 ny01.mysite.com systemd[1]: Stopped Service for snap application nextcloud.apache.
Oct 09 21:24:22 ny01.mysite.com systemd[1]: Started Service for snap application nextcloud.apache.
Oct 09 21:24:22 ny01.mysite.com /usr/bin/snap[5168]: cmd.go:105: DEBUG: restarting into "/snap/core/current/usr/bin/snap"
Oct 09 21:24:23 ny01.mysite.com nextcloud.apache[5168]: Making sure nextcloud is setup...



PHP

Status

● snap.nextcloud.php-fpm.service - Service for snap application nextcloud.php-fpm
   Loaded: loaded (/etc/systemd/system/snap.nextcloud.php-fpm.service; enabled; vendor preset: enabled)
   Active: inactive (dead) since Tue 2018-10-09 21:20:10 UTC; 14min ago
  Process: 3412 ExecStart=/usr/bin/snap run nextcloud.php-fpm (code=killed, signal=TERM)
 Main PID: 3412 (code=killed, signal=TERM)
      CPU: 345ms

Oct 09 21:17:52 ny01.mysite.com systemd[1]: Stopped Service for snap application nextcloud.php-fpm.
Oct 09 21:17:52 ny01.mysite.com systemd[1]: Started Service for snap application nextcloud.php-fpm.
Oct 09 21:17:52 ny01.mysite.com /usr/bin/snap[3412]: cmd.go:105: DEBUG: restarting into "/snap/core/current/usr/bin/snap"
Oct 09 21:20:10 ny01.mysite.com nextcloud.php-fpm[3412]: Waiting for MySQL...
Oct 09 21:20:10 ny01.mysite.com systemd[1]: Stopping Service for snap application nextcloud.php-fpm...
Oct 09 21:20:10 ny01.mysite.com systemd[1]: Stopped Service for snap application nextcloud.php-fpm.

Journal

-- Logs begin at Tue 2018-10-09 21:15:02 UTC, end at Tue 2018-10-09 21:34:40 UTC. --
Oct 09 21:15:04 ny01.mysite.com systemd[1]: Started Service for snap application nextcloud.php-fpm.
Oct 09 21:15:05 ny01.mysite.com /usr/bin/snap[634]: cmd.go:105: DEBUG: restarting into "/snap/core/current/usr/bin/snap"
Oct 09 21:17:52 ny01.mysite.com systemd[1]: Stopping Service for snap application nextcloud.php-fpm...
Oct 09 21:17:52 ny01.mysite.com nextcloud.php-fpm[634]: Waiting for MySQL...
Oct 09 21:17:52 ny01.mysite.com systemd[1]: Stopped Service for snap application nextcloud.php-fpm.
Oct 09 21:17:52 ny01.mysite.com systemd[1]: Started Service for snap application nextcloud.php-fpm.
Oct 09 21:17:52 ny01.mysite.com /usr/bin/snap[3412]: cmd.go:105: DEBUG: restarting into "/snap/core/current/usr/bin/snap"
Oct 09 21:20:10 ny01.mysite.com nextcloud.php-fpm[3412]: Waiting for MySQL...
Oct 09 21:20:10 ny01.mysite.com systemd[1]: Stopping Service for snap application nextcloud.php-fpm...
Oct 09 21:20:10 ny01.mysite.com systemd[1]: Stopped Service for snap application nextcloud.php-fpm.



MySQL

Status

● snap.nextcloud.mysql.service - Service for snap application nextcloud.mysql
   Loaded: loaded (/etc/systemd/system/snap.nextcloud.mysql.service; enabled; vendor preset: enabled)
   Active: active (running) since Tue 2018-10-09 21:24:53 UTC; 9min ago
  Process: 5496 ExecStop=/usr/bin/snap run --command=stop nextcloud.mysql (code=exited, status=0/SUCCESS)
 Main PID: 5519 (start_mysql)
    Tasks: 2 (limit: 4915)
   Memory: 2.8M
      CPU: 2.137s
   CGroup: /system.slice/snap.nextcloud.mysql.service
           ├─5519 /bin/sh /snap/nextcloud/9077/bin/start_mysql
           └─8045 sleep 1

Oct 09 21:24:53 ny01.mysite.com nextcloud.mysql[5519]: Starting MySQL
Oct 09 21:24:53 ny01.mysite.com mysqld_safe[6014]: Logging to '/var/log/mysql/error.log'.
Oct 09 21:24:53 ny01.mysite.com mysqld_safe[6050]: Starting mysqld daemon with databases from /var/snap/nextcloud/9077/mysql
Oct 09 21:24:54 ny01.mysite.com mysqld[6055]: /snap/nextcloud/9077/bin/mysqld (mysqld 5.7.22) starting as process 6055 ...
Oct 09 21:24:54 ny01.mysite.com mysqld[6055]: failed to set datadir to /var/snap/nextcloud/9077/mysql/
Oct 09 21:24:54 ny01.mysite.com mysqld[6055]: Aborting
Oct 09 21:24:54 ny01.mysite.com mysqld[6055]: Binlog end
Oct 09 21:24:54 ny01.mysite.com mysqld[6055]: /snap/nextcloud/9077/bin/mysqld: Shutdown complete
Oct 09 21:24:54 ny01.mysite.com mysqld_safe[6061]: mysqld from pid file /tmp/pids/mysql.pid ended
Oct 09 21:24:54 ny01.mysite.com nextcloud.mysql[5519]: . * The server quit without updating PID file (/tmp/pids/mysql.pid).

Journal

-- Logs begin at Tue 2018-10-09 21:15:02 UTC, end at Tue 2018-10-09 21:34:40 UTC. --
Oct 09 21:15:04 ny01.mysite.com systemd[1]: Started Service for snap application nextcloud.mysql.
Oct 09 21:15:05 ny01.mysite.com /usr/bin/snap[637]: cmd.go:105: DEBUG: restarting into "/snap/core/current/usr/bin/snap"
Oct 09 21:15:12 ny01.mysite.com nextcloud.mysql[637]: 2018-10-09T21:15:11.751572Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
Oct 09 21:15:12 ny01.mysite.com nextcloud.mysql[637]: 2018-10-09T21:15:12.191873Z 0 [ERROR] --initialize specified but the data directory has files in it. Aborting.
Oct 09 21:15:12 ny01.mysite.com nextcloud.mysql[637]: 2018-10-09T21:15:12.192932Z 0 [ERROR] Aborting
Oct 09 21:15:12 ny01.mysite.com nextcloud.mysql[637]: touch: cannot touch '/tmp/locks/mysql-setup': No such file or directory
Oct 09 21:15:13 ny01.mysite.com nextcloud.mysql[637]: Starting MySQL
Oct 09 21:15:16 ny01.mysite.com mysqld_safe[2144]: Logging to '/var/log/mysql/error.log'.
Oct 09 21:15:16 ny01.mysite.com mysqld_safe[2226]: Starting mysqld daemon with databases from /var/snap/nextcloud/9077/mysql
Oct 09 21:15:16 ny01.mysite.com mysqld[2234]: /snap/nextcloud/9077/bin/mysqld (mysqld 5.7.22) starting as process 2234 ...
Oct 09 21:15:16 ny01.mysite.com mysqld[2234]: failed to set datadir to /var/snap/nextcloud/9077/mysql/
Oct 09 21:15:16 ny01.mysite.com mysqld[2234]: Aborting
Oct 09 21:15:16 ny01.mysite.com mysqld[2234]: Binlog end
Oct 09 21:15:16 ny01.mysite.com mysqld[2234]: /snap/nextcloud/9077/bin/mysqld: Shutdown complete
Oct 09 21:15:17 ny01.mysite.com mysqld_safe[2260]: mysqld from pid file /tmp/pids/mysql.pid ended
Oct 09 21:15:17 ny01.mysite.com nextcloud.mysql[637]: ... * The server quit without updating PID file (/tmp/pids/mysql.pid).
Oct 09 21:20:10 ny01.mysite.com systemd[1]: Stopping Service for snap application nextcloud.mysql...
Oct 09 21:20:10 ny01.mysite.com /usr/bin/snap[3908]: cmd.go:105: DEBUG: restarting into "/snap/core/current/usr/bin/snap"
Oct 09 21:20:11 ny01.mysite.com nextcloud.mysql[3908]:  * MySQL server PID file could not be found!
Oct 09 21:20:11 ny01.mysite.com nextcloud.mysql[637]: Waiting for MySQL...
Oct 09 21:20:11 ny01.mysite.com systemd[1]: Stopped Service for snap application nextcloud.mysql.
Oct 09 21:24:22 ny01.mysite.com systemd[1]: Started Service for snap application nextcloud.mysql.
Oct 09 21:24:22 ny01.mysite.com /usr/bin/snap[4803]: cmd.go:105: DEBUG: restarting into "/snap/core/current/usr/bin/snap"
Oct 09 21:24:22 ny01.mysite.com nextcloud.mysql[4803]: 2018-10-09T21:24:22.535085Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
Oct 09 21:24:22 ny01.mysite.com nextcloud.mysql[4803]: 2018-10-09T21:24:22.538373Z 0 [ERROR] --initialize specified but the data directory has files in it. Aborting.
Oct 09 21:24:22 ny01.mysite.com nextcloud.mysql[4803]: 2018-10-09T21:24:22.540622Z 0 [ERROR] Aborting
Oct 09 21:24:22 ny01.mysite.com nextcloud.mysql[4803]: touch: cannot touch '/tmp/locks/mysql-setup': No such file or directory
Oct 09 21:24:22 ny01.mysite.com nextcloud.mysql[4803]: Starting MySQL
Oct 09 21:24:23 ny01.mysite.com mysqld_safe[5349]: Logging to '/var/log/mysql/error.log'.
Oct 09 21:24:23 ny01.mysite.com mysqld_safe[5385]: Starting mysqld daemon with databases from /var/snap/nextcloud/9077/mysql
Oct 09 21:24:23 ny01.mysite.com mysqld[5390]: /snap/nextcloud/9077/bin/mysqld (mysqld 5.7.22) starting as process 5390 ...
Oct 09 21:24:23 ny01.mysite.com mysqld[5390]: failed to set datadir to /var/snap/nextcloud/9077/mysql/
Oct 09 21:24:23 ny01.mysite.com mysqld[5390]: Aborting
Oct 09 21:24:23 ny01.mysite.com mysqld[5390]: Binlog end
Oct 09 21:24:23 ny01.mysite.com mysqld[5390]: /snap/nextcloud/9077/bin/mysqld: Shutdown complete
Oct 09 21:24:23 ny01.mysite.com mysqld_safe[5395]: mysqld from pid file /tmp/pids/mysql.pid ended
Oct 09 21:24:24 ny01.mysite.com nextcloud.mysql[4803]: .. * The server quit without updating PID file (/tmp/pids/mysql.pid).
Oct 09 21:24:52 ny01.mysite.com systemd[1]: Stopping Service for snap application nextcloud.mysql...
Oct 09 21:24:52 ny01.mysite.com /usr/bin/snap[5496]: cmd.go:105: DEBUG: restarting into "/snap/core/current/usr/bin/snap"
Oct 09 21:24:53 ny01.mysite.com nextcloud.mysql[5496]:  * MySQL server PID file could not be found!
Oct 09 21:24:53 ny01.mysite.com nextcloud.mysql[4803]: Waiting for MySQL...
Oct 09 21:24:53 ny01.mysite.com systemd[1]: Stopped Service for snap application nextcloud.mysql.
Oct 09 21:24:53 ny01.mysite.com systemd[1]: Started Service for snap application nextcloud.mysql.
Oct 09 21:24:53 ny01.mysite.com /usr/bin/snap[5519]: cmd.go:105: DEBUG: restarting into "/snap/core/current/usr/bin/snap"
Oct 09 21:24:53 ny01.mysite.com nextcloud.mysql[5519]: 2018-10-09T21:24:53.211482Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
Oct 09 21:24:53 ny01.mysite.com nextcloud.mysql[5519]: 2018-10-09T21:24:53.213620Z 0 [ERROR] --initialize specified but the data directory has files in it. Aborting.
Oct 09 21:24:53 ny01.mysite.com nextcloud.mysql[5519]: 2018-10-09T21:24:53.215299Z 0 [ERROR] Aborting
Oct 09 21:24:53 ny01.mysite.com nextcloud.mysql[5519]: touch: cannot touch '/tmp/locks/mysql-setup': No such file or directory
Oct 09 21:24:53 ny01.mysite.com nextcloud.mysql[5519]: Starting MySQL
Oct 09 21:24:53 ny01.mysite.com mysqld_safe[6014]: Logging to '/var/log/mysql/error.log'.
Oct 09 21:24:53 ny01.mysite.com mysqld_safe[6050]: Starting mysqld daemon with databases from /var/snap/nextcloud/9077/mysql
Oct 09 21:24:54 ny01.mysite.com mysqld[6055]: /snap/nextcloud/9077/bin/mysqld (mysqld 5.7.22) starting as process 6055 ...
Oct 09 21:24:54 ny01.mysite.com mysqld[6055]: failed to set datadir to /var/snap/nextcloud/9077/mysql/
Oct 09 21:24:54 ny01.mysite.com mysqld[6055]: Aborting
Oct 09 21:24:54 ny01.mysite.com mysqld[6055]: Binlog end
Oct 09 21:24:54 ny01.mysite.com mysqld[6055]: /snap/nextcloud/9077/bin/mysqld: Shutdown complete
Oct 09 21:24:54 ny01.mysite.com mysqld_safe[6061]: mysqld from pid file /tmp/pids/mysql.pid ended
Oct 09 21:24:54 ny01.mysite.com nextcloud.mysql[5519]: . * The server quit without updating PID file (/tmp/pids/mysql.pid).



Redis

Status

● snap.nextcloud.redis-server.service - Service for snap application nextcloud.redis-server
   Loaded: loaded (/etc/systemd/system/snap.nextcloud.redis-server.service; enabled; vendor preset: enabled)
   Active: inactive (dead) since Tue 2018-10-09 21:20:11 UTC; 14min ago
  Process: 638 ExecStart=/usr/bin/snap run nextcloud.redis-server (code=killed, signal=TERM)
 Main PID: 638 (code=killed, signal=TERM)
      CPU: 874ms

Oct 09 21:15:05 ny01.mysite.com /usr/bin/snap[638]: cmd.go:105: DEBUG: restarting into "/snap/core/current/usr/bin/snap"
Oct 09 21:15:04 ny01.mysite.com systemd[1]: Started Service for snap application nextcloud.redis-server.
Oct 09 21:20:10 ny01.mysite.com systemd[1]: Stopping Service for snap application nextcloud.redis-server...
Oct 09 21:20:11 ny01.mysite.com systemd[1]: Stopped Service for snap application nextcloud.redis-server.

Journal

-- Logs begin at Tue 2018-10-09 21:15:02 UTC, end at Tue 2018-10-09 21:34:40 UTC. --
Oct 09 21:15:05 ny01.mysite.com /usr/bin/snap[638]: cmd.go:105: DEBUG: restarting into "/snap/core/current/usr/bin/snap"
Oct 09 21:15:04 ny01.mysite.com systemd[1]: Started Service for snap application nextcloud.redis-server.
Oct 09 21:20:10 ny01.mysite.com systemd[1]: Stopping Service for snap application nextcloud.redis-server...
Oct 09 21:20:11 ny01.mysite.com systemd[1]: Stopped Service for snap application nextcloud.redis-server.



mDNS Publisher

Status

● snap.nextcloud.mdns-publisher.service - Service for snap application nextcloud.mdns-publisher
   Loaded: loaded (/etc/systemd/system/snap.nextcloud.mdns-publisher.service; enabled; vendor preset: enabled)
   Active: inactive (dead) since Tue 2018-10-09 21:20:10 UTC; 14min ago
  Process: 642 ExecStart=/usr/bin/snap run nextcloud.mdns-publisher (code=killed, signal=TERM)
 Main PID: 642 (code=killed, signal=TERM)
      CPU: 275ms

Oct 09 21:15:05 ny01.mysite.com /usr/bin/snap[642]: cmd.go:105: DEBUG: restarting into "/snap/core/current/usr/bin/snap"
Oct 09 21:15:04 ny01.mysite.com systemd[1]: Started Service for snap application nextcloud.mdns-publisher.
Oct 09 21:15:10 ny01.mysite.com nextcloud.mdns-publisher[642]: 2018/10/09 21:15:10 Publishing ny01.local -> [207.148.82.219 fe80::5400:1ff:fe5d:eabf] with 60-second TTL
Oct 09 21:20:10 ny01.mysite.com systemd[1]: Stopping Service for snap application nextcloud.mdns-publisher...
Oct 09 21:20:10 ny01.mysite.com systemd[1]: Stopped Service for snap application nextcloud.mdns-publisher.

Journal

-- Logs begin at Tue 2018-10-09 21:15:02 UTC, end at Tue 2018-10-09 21:34:40 UTC. --
Oct 09 21:15:05 ny01.mysite.com /usr/bin/snap[642]: cmd.go:105: DEBUG: restarting into "/snap/core/current/usr/bin/snap"
Oct 09 21:15:04 ny01.mysite.com systemd[1]: Started Service for snap application nextcloud.mdns-publisher.
Oct 09 21:15:10 ny01.mysite.com nextcloud.mdns-publisher[642]: 2018/10/09 21:15:10 Publishing ny01.local -> [207.148.82.219 fe80::5400:1ff:fe5d:eabf] with 60-second TTL
Oct 09 21:20:10 ny01.mysite.com systemd[1]: Stopping Service for snap application nextcloud.mdns-publisher...
Oct 09 21:20:10 ny01.mysite.com systemd[1]: Stopped Service for snap application nextcloud.mdns-publisher.



Certificate Renewer

Status

● snap.nextcloud.renew-certs.service - Service for snap application nextcloud.renew-certs
   Loaded: loaded (/etc/systemd/system/snap.nextcloud.renew-certs.service; enabled; vendor preset: enabled)
   Active: inactive (dead) since Tue 2018-10-09 21:20:10 UTC; 14min ago
  Process: 644 ExecStart=/usr/bin/snap run nextcloud.renew-certs (code=killed, signal=TERM)
 Main PID: 644 (code=killed, signal=TERM)
      CPU: 3.560s

Oct 09 21:15:05 ny01.mysite.com /usr/bin/snap[644]: cmd.go:105: DEBUG: restarting into "/snap/core/current/usr/bin/snap"
Oct 09 21:15:04 ny01.mysite.com systemd[1]: Started Service for snap application nextcloud.renew-certs.
Oct 09 21:15:19 ny01.mysite.com nextcloud.renew-certs[644]: Saving debug log to /var/snap/nextcloud/current/certs/certbot/logs/letsencrypt.log
Oct 09 21:15:19 ny01.mysite.com nextcloud.renew-certs[644]: - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
Oct 09 21:15:19 ny01.mysite.com nextcloud.renew-certs[644]: No renewals were attempted.
Oct 09 21:15:19 ny01.mysite.com nextcloud.renew-certs[644]: No hooks were run.
Oct 09 21:15:19 ny01.mysite.com nextcloud.renew-certs[644]: - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
Oct 09 21:20:10 ny01.mysite.com systemd[1]: Stopping Service for snap application nextcloud.renew-certs...
Oct 09 21:20:10 ny01.mysite.com systemd[1]: Stopped Service for snap application nextcloud.renew-certs.

Journal

-- Logs begin at Tue 2018-10-09 21:15:02 UTC, end at Tue 2018-10-09 21:34:40 UTC. --
Oct 09 21:15:05 ny01.mysite.com /usr/bin/snap[644]: cmd.go:105: DEBUG: restarting into "/snap/core/current/usr/bin/snap"
Oct 09 21:15:04 ny01.mysite.com systemd[1]: Started Service for snap application nextcloud.renew-certs.
Oct 09 21:15:19 ny01.mysite.com nextcloud.renew-certs[644]: Saving debug log to /var/snap/nextcloud/current/certs/certbot/logs/letsencrypt.log
Oct 09 21:15:19 ny01.mysite.com nextcloud.renew-certs[644]: - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
Oct 09 21:15:19 ny01.mysite.com nextcloud.renew-certs[644]: No renewals were attempted.
Oct 09 21:15:19 ny01.mysite.com nextcloud.renew-certs[644]: No hooks were run.
Oct 09 21:15:19 ny01.mysite.com nextcloud.renew-certs[644]: - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
Oct 09 21:20:10 ny01.mysite.com systemd[1]: Stopping Service for snap application nextcloud.renew-certs...
Oct 09 21:20:10 ny01.mysite.com systemd[1]: Stopped Service for snap application nextcloud.renew-certs.



Nextcloud Cron

Status

● snap.nextcloud.nextcloud-cron.service - Service for snap application nextcloud.nextcloud-cron
   Loaded: loaded (/etc/systemd/system/snap.nextcloud.nextcloud-cron.service; enabled; vendor preset: enabled)
   Active: inactive (dead) since Tue 2018-10-09 21:20:10 UTC; 14min ago
  Process: 635 ExecStart=/usr/bin/snap run nextcloud.nextcloud-cron (code=killed, signal=TERM)
 Main PID: 635 (code=killed, signal=TERM)
      CPU: 1.504s

Oct 09 21:15:04 ny01.mysite.com systemd[1]: Started Service for snap application nextcloud.nextcloud-cron.
Oct 09 21:15:05 ny01.mysite.com /usr/bin/snap[635]: cmd.go:105: DEBUG: restarting into "/snap/core/current/usr/bin/snap"
Oct 09 21:15:09 ny01.mysite.com nextcloud.nextcloud-cron[635]: Waiting for Nextcloud config dir... done
Oct 09 21:20:10 ny01.mysite.com systemd[1]: Stopping Service for snap application nextcloud.nextcloud-cron...
Oct 09 21:20:10 ny01.mysite.com systemd[1]: Stopped Service for snap application nextcloud.nextcloud-cron.

Journal

-- Logs begin at Tue 2018-10-09 21:15:02 UTC, end at Tue 2018-10-09 21:34:40 UTC. --
Oct 09 21:15:04 ny01.mysite.com systemd[1]: Started Service for snap application nextcloud.nextcloud-cron.
Oct 09 21:15:05 ny01.mysite.com /usr/bin/snap[635]: cmd.go:105: DEBUG: restarting into "/snap/core/current/usr/bin/snap"
Oct 09 21:15:09 ny01.mysite.com nextcloud.nextcloud-cron[635]: Waiting for Nextcloud config dir... done
Oct 09 21:20:10 ny01.mysite.com systemd[1]: Stopping Service for snap application nextcloud.nextcloud-cron...
Oct 09 21:20:10 ny01.mysite.com systemd[1]: Stopped Service for snap application nextcloud.nextcloud-cron.

`

kukulau picture kukulau on 10 Oct 2018

Given that we are on different kernels, and rolling back did not make a difference, it seems like this is not caused by changes in the kernel. I don't see any other recent updates that looks related.

Snap appears to self update:

$ snap --version
snap    2.35.2
snapd   2.35.2
series  16
debian  9
kernel  4.18.0-0.bpo.1-amd64

So I wonder if a change in snap now depends on something missing in debian stable, maybe an update to apparmor? Maybe this is triggered by the first reboot after the snap update?

samtygier picture samtygier on 10 Oct 2018

I think I have found a solution. I also had mysql installed outside the snap. If I remove that and restart the snap

sudo apt remove mysql-common
sudo snap restart nextcloud

So I wonder if the snap is mistakingly launching the external mysql instead of the internal one?

samtygier picture samtygier on 10 Oct 2018
👍4

That seems to make sense. I also have a msyql instance running outside of the snap. It's running my Kodi database among other things so I can remove it to test what you say, but it sounds right from what the logs say as well.

lakerssuperman picture lakerssuperman on 10 Oct 2018

Ah, that does indeed make sense: snaps on Debian aren't confined like they are on Ubuntu, which means it's actually possible for exactly that to happen.

kyrofa picture kyrofa on 11 Oct 2018

So here's the weird thing about this, assuming that's what's happening. Confined snaps (like Nextcloud) execute with the core snap as its environment, think of it like a chroot. /usr/bin isn't the host's /usr/bin, it's the core snap's. The host filesystem is available in /var/lib/snapd/hostfs or something similar. I can't reason how mysql in there is happening to be on the PATH.

kyrofa picture kyrofa on 14 Oct 2018

Maybe it not launching /usr/bin/mysqld, but something about having mysql installed outside the snap makes an effect. Have you managed to reproduce it? I can in a debian vm.

samtygier picture samtygier on 14 Oct 2018

After upgrade raspbian ,I got this:
2018-10-17T01:01:33.230637Z mysqld_safe Logging to '/var/log/mysql/error.log'.
2018-10-17T01:01:33.417726Z mysqld_safe Starting mysqld daemon with databases from /var/snap/nextcloud/8973/mysql
mysqld: Can't change dir to '/var/snap/nextcloud/8973/mysql/' (Errcode: 13 - Permission denied)
2018-10-17T01:01:33.835248Z 0 [Warning] Ignoring user change to 'root' because the user was set to 'mysql' earlier on the command line

2018-10-17T01:01:33.835699Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2018-10-17T01:01:33.836002Z 0 [Note] --secure-file-priv is set to NULL. Operations related to importing and exporting data are disabled
2018-10-17T01:01:33.836518Z 0 [Note] /snap/nextcloud/8973/bin/mysqld (mysqld 5.7.22) starting as process 23348 ...
2018-10-17T01:01:33.867453Z 0 [ERROR] failed to set datadir to /var/snap/nextcloud/8973/mysql/
2018-10-17T01:01:33.867685Z 0 [ERROR] Aborting

2018-10-17T01:01:33.867836Z 0 [Note] Binlog end
2018-10-17T01:01:33.868195Z 0 [Note] /snap/nextcloud/8973/bin/mysqld: Shutdown complete

2018-10-17T01:01:33.947817Z mysqld_safe mysqld from pid file /tmp/pids/mysql.pid ended

shaokuuipo picture shaokuuipo on 17 Oct 2018

I'm going to pretend this is a dupe of #913, even though this one was logged first.

kyrofa picture kyrofa on 11 Oct 2019
Was this page helpful?
0 / 5 - 0 ratings

Related issues

Seferi picture Seferi  ·  5Comments
aptanet picture aptanet  ·  7Comments
tinokizis picture tinokizis  ·  8Comments
WereCatf picture WereCatf  ·  3Comments
RadZaeem picture RadZaeem  ·  8Comments