System not working after apt upgrade

[zartarr88]

Hi guys,
I recently upgraded from RPi 3 to 4 ; and when I did apt update ; I believe Mariadb got upgraded ; because I'm running into a similar issue possibly. More specifically;

Aug 03 23:12:04 DietPi /etc/mysql/debian-start[28785]: Upgrading MySQL tables if necessary.
Aug 03 23:12:04 DietPi /etc/mysql/debian-start[28788]: /usr/bin/mysql_upgrade: unknown variable 'sync_binlog=10'

any workaround on this ?

[Joulinar]

pls can you post you error log. I guess you issue is different.

[zartarr88]

What I noticed after the upgrade was for some reason all my dietpi-services were not 'enabled' so although status would be online they weren't enabled at boot ; so somehow that got messed up . The system also hangs at timesyncd (NTP stuff) and mariadb ; so one by one I'm just trying to troubleshoot.

Code: Select all

● mariadb.service - MariaDB 10.3.23 database server
   Loaded: loaded (/lib/systemd/system/mariadb.service; enabled; vendor preset: enabled)
   Active: active (running) since Mon 2020-08-03 23:45:42 BST; 6s ago
     Docs: man:mysqld(8)
           https://mariadb.com/kb/en/library/systemd/
  Process: 3726 ExecStartPre=/usr/bin/install -m 755 -o mysql -g root -d /var/run/mysqld (code=exited, status=0/SUCCESS)
  Process: 3727 ExecStartPre=/bin/sh -c systemctl unset-environment _WSREP_START_POSITION (code=exited, status=0/SUCCESS)
  Process: 3729 ExecStartPre=/bin/sh -c [ ! -e /usr/bin/galera_recovery ] && VAR= ||   VAR=`cd /usr/bin/..; /usr/bin/galera_recove
ry`; [ $? -eq 0 ]   && systemctl set-environment _WSREP_START_POSITION=$VAR || exit 1 (code=exited, status=0/SUCCESS)
  Process: 3820 ExecStartPost=/bin/sh -c systemctl unset-environment _WSREP_START_POSITION (code=exited, status=0/SUCCESS)
  Process: 3822 ExecStartPost=/etc/mysql/debian-start (code=exited, status=0/SUCCESS)
 Main PID: 3785 (mysqld)
   Status: "Taking your SQL requests now..."
    Tasks: 34 (limit: 4915)
   CGroup: /system.slice/mariadb.service
           ├─3785 /usr/sbin/mysqld
           ├─3823 /bin/bash /etc/mysql/debian-start
           ├─3846 /usr/bin/mysql --defaults-file=/etc/mysql/debian.cnf --skip-column-names --batch -e       select concat('select 
count(*) into @discard from `',                     TABLE_SCHEMA, '`.`', TABLE_NAME, '`')        from information_schema.TABLES wh
ere TABLE_SCHEMA<>'INFORMATION_SCHEMA' and TABLE_SCHEMA<>'PERFORMANCE_SCHEMA' and ( ENGINE='MyISAM' or ENGINE='Aria' )
           └─3847 xargs -i /usr/bin/mysql --defaults-file=/etc/mysql/debian.cnf --skip-column-names --silent --batch --force -e {}

Aug 03 23:45:42 DietPi systemd[1]: Starting MariaDB 10.3.23 database server...
Aug 03 23:45:42 DietPi mysqld[3785]: 2020-08-03 23:45:42 0 [Note] /usr/sbin/mysqld (mysqld 10.3.23-MariaDB-0+deb10u1) starting as 
process 3785 ...
Aug 03 23:45:42 DietPi systemd[1]: Started MariaDB 10.3.23 database server.
Aug 03 23:45:42 DietPi /etc/mysql/debian-start[3824]: Upgrading MySQL tables if necessary.
Aug 03 23:45:42 DietPi /etc/mysql/debian-start[3827]: /usr/bin/mysql_upgrade: the '--basedir' option is al
ways ignored
Aug 03 23:45:42 DietPi /etc/mysql/debian-start[3827]: Looking for 'mysql' as: /usr/bin/mysql
Aug 03 23:45:42 DietPi /etc/mysql/debian-start[3827]: Looking for 'mysqlcheck' as: /usr/bin/mysqlcheck
Aug 03 23:45:42 DietPi /etc/mysql/debian-start[3827]: This installation of MySQL is already upgraded to 10
.3.23-MariaDB, use --force if you still need to run mysql_upgrade
Aug 03 23:45:42 DietPi /etc/mysql/debian-start[3835]: Checking for insecure root accounts.
Aug 03 23:45:43 DietPi /etc/mysql/debian-start[3843]: Triggering myisam-recover for all MyISAM tables and aria-recover for all Ari
a tables

[Joulinar]

pls can you post your error log

Code: Select all

systemctl restart mariadb.service
cat /var/log/mysql/error.log

btw your service is stating Active: active (running)

[zartarr88]

Sorry about that,

Code: Select all

root@DietPi:~# cat /var/log/mysql/error.log
2020-08-04  0:01:40 0 [Note] /usr/sbin/mysqld (initiated by: unknown): Normal shutdown
2020-08-04  0:01:40 0 [Note] Event Scheduler: Purging the queue. 0 events
2020-08-04  0:01:40 0 [Note] InnoDB: FTS optimize thread exiting.
2020-08-04  0:01:41 0 [Note] InnoDB: Starting shutdown...
2020-08-04  0:01:41 0 [Note] InnoDB: Buffer pool(s) load aborted due to user instigated abort at 200804  0:01:41
2020-08-04  0:01:41 0 [Note] InnoDB: Dumping of buffer pool not started as load was incomplete
2020-08-04  0:01:43 0 [Note] InnoDB: Shutdown completed; log sequence number 4683516193; transaction id 15858200
2020-08-04  0:01:43 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2020-08-04  0:01:43 0 [Note] /usr/sbin/mysqld: Shutdown complete

2020-08-04  0:01:44 0 [Note] InnoDB: Using Linux native AIO
2020-08-04  0:01:44 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2020-08-04  0:01:44 0 [Note] InnoDB: Uses event mutexes
2020-08-04  0:01:44 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2020-08-04  0:01:44 0 [Note] InnoDB: Number of pools: 1
2020-08-04  0:01:44 0 [Note] InnoDB: Using generic crc32 instructions
2020-08-04  0:01:44 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2020-08-04  0:01:44 0 [Note] InnoDB: Completed initialization of buffer pool
2020-08-04  0:01:44 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2020-08-04  0:01:44 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2020-08-04  0:01:44 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2020-08-04  0:01:44 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2020-08-04  0:01:44 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2020-08-04  0:01:44 0 [Note] InnoDB: Waiting for purge to start
2020-08-04  0:01:44 0 [Note] InnoDB: 10.3.23 started; log sequence number 4683516193; transaction id 15858199
2020-08-04  0:01:44 0 [Note] InnoDB: Loading buffer pool(s) from /mnt/b160aab4-f893-4c78-9877-8c3f16488b60/dietpi_userdata/mysql/ib_buffer_pool
2020-08-04  0:01:44 0 [Note] Plugin 'FEEDBACK' is disabled.
2020-08-04  0:01:44 0 [Note] Server socket created on IP: '127.0.0.1'.
2020-08-04  0:01:44 0 [Note] Reading of all Master_info entries succeeded
2020-08-04  0:01:44 0 [Note] Added new Master_info '' to hash table
2020-08-04  0:01:44 0 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.3.23-MariaDB-0+deb10u1'  socket: '/run/mysqld/mysqld.sock'  port: 3306  Raspbian 10

[Joulinar]

what is now the issue with MariaDB? Your service is running:

Code: Select all

● mariadb.service - MariaDB 10.3.23 database server
   Loaded: loaded (/lib/systemd/system/mariadb.service; enabled; vendor preset: enabled)
   Active: active (running) since Mon 2020-08-03 23:45:42 BST; 6s ago

and MariaDB is waiting for connections:

Code: Select all

2020-08-04  0:01:44 0 [Note] /usr/sbin/mysqld: ready for connections.

[zartarr88]

oh ,
well when I go to my nextcloud site I get "404 Not Found"

and because the tymdsyncd would go 1/60... 2/60 and hang and mariadb would hang, Dietpi-Postboot ... so I thought it was related .

I use dietpi for nextcloud purely and since its not working after recent upgrade and have very few things installed I'm just going off of the visual cues

[Joulinar]

well HTTP 404 means, that the web server could not find the page you are looking for

https://en.wikipedia.org/wiki/HTTP_404

BTW: I moved the topic into a new post

[zartarr88]

So I think the reason for the confusion is because its hit-or-miss ; not consistent
2 things are consistent
1) dietpi-postboot hangs when its starting services at boot right at the mariadb service FOR A LONG TIME
2) sometimes it gets into LXDE and my nextcloud server is up and sometimes it isn't . For past few days I didn't reboot because it was working and now today I have a better output for you:
I don't know why there are so many mysql lines ; it wasn't the case pre apt-get update I did

Code: Select all

root@DietPi:~# systemctl status mariadb
● mariadb.service - MariaDB 10.3.23 database server
   Loaded: loaded (/lib/systemd/system/mariadb.service; enabled; vendor preset: 
enabled)
   Active: active (running) since Mon 2020-08-10 18:36:04 BST; 44s ag
o
     Docs: man:mysqld(8)
           https://mariadb.com/kb/en/library/systemd/
  Process: 24566 ExecStartPre=/usr/bin/install -m 755 -o mysql -g root -d /var/r
un/mysqld (code=exited, status=0/SUCCESS)
  Process: 24567 ExecStartPre=/bin/sh -c systemctl unset-environment _WSREP_STAR
T_POSITION (code=exited, status=0/SUCCESS)
  Process: 24569 ExecStartPre=/bin/sh -c [ ! -e /usr/bin/galera_recovery ] && VA
R= ||   VAR=`cd /usr/bin/..; /usr/bin/galera_recovery`; [ $? -eq 0 ]   && system
ctl set-environment _WSREP_START_POSITION=$VAR || exit 1 (code=exited, status=0/
SUCCESS)
  Process: 24667 ExecStartPost=/bin/sh -c systemctl unset-environment _WSREP_STA
RT_POSITION (code=exited, status=0/SUCCESS)
  Process: 24669 ExecStartPost=/etc/mysql/debian-start (code=exited, status=0/SU
CCESS)
 Main PID: 24635 (mysqld)
   Status: "Taking your SQL requests now..."
    Tasks: 35 (limit: 4915)
   CGroup: /system.slice/mariadb.service
           ├─24635 /usr/sbin/mysqld
           ├─24670 /bin/bash /etc/mysql/debian-start
           ├─24701 /usr/bin/mysql --defaults-file=/etc/mysql/debian.cnf --skip-c
olumn-names --batch -e       select concat('select count(*) into @discard from `
',                     TABLE_SCHEMA, '`.`', TABLE_NAME, '`')        from informa
tion_schema.TABLES where TABLE_SCHEMA<>'INFORMATION_SCHEMA' and TABLE_SCHEMA<>'P
ERFORMANCE_SCHEMA' and ( ENGINE='MyISAM' or ENGINE='Aria' )
           └─24702 xargs -i /usr/bin/mysql --defaults-file=/etc/mysql/debian.cnf
 --skip-column-names --silent --batch --force -e {}

Aug 10 18:36:04 DietPi systemd[1]: Starting MariaDB 10.3.23 database server...
Aug 10 18:36:04 DietPi mysqld[24635]: 2020-08-10 18:36:04 0 [Note] /usr/sbin/mys
qld (mysqld 10.3.23-MariaDB-0+deb10u1) starting as process 24635 ...
Aug 10 18:36:04 DietPi systemd[1]: Started MariaDB 10.3.23 database server.
Aug 10 18:36:04 DietPi /etc/mysql/debian-start[24671]: Upgrading MySQL tables if
 necessary.
Aug 10 18:36:05 DietPi /etc/mysql/debian-start[24676]: /
usr/bin/mysql_upgrade: the '--basedir' option is always ignored
Aug 10 18:36:05 DietPi /etc/mysql/debian-start[24676]: L
ooking for 'mysql' as: /usr/bin/mysql
Aug 10 18:36:05 DietPi /etc/mysql/debian-start[24676]: L
ooking for 'mysqlcheck' as: /usr/bin/mysqlcheck
Aug 10 18:36:05 DietPi /etc/mysql/debian-start[24676]: T
his installation of MySQL is already upgraded to 10.3.23-MariaDB, use --force if
 you still need to run mysql_upgrade
Aug 10 18:36:05 DietPi /etc/mysql/debian-start[24694]: Checking for insecure roo
t accounts.
Aug 10 18:36:05 DietPi /etc/mysql/debian-start[24698]: Triggering myisam-recover
 for all MyISAM tables and aria-recover for all Aria tables

and... systemd-analyze blame confirms

Code: Select all

root@DietPi:~# systemd-analyze blame
   10min 32.628s mariadb.service
         31.834s dietpi-boot.service
         31.771s dietpi-preboot.service
          4.534s proftpd.service
          3.849s php7.3-fpm.service
          2.510s nginx.service
          1.739s redis-server.service
          1.119s dev-mmcblk0p2.device

[Joulinar]

your database is starting. It's in active status and ready for connection. However your database is starting extremely slow, which is confirmed by systemd-analyze blame due to the extrem time stamp. Looks like it's doing some kind of recovery during start-up which is taking time. did you had a look to MariaDB error log?