System pro module - update from 10.13.66-19 to 10.13.66-20 hung?

byrnejb · June 17, 2017, 8:15pm

FreePBX Distro 10.13.66-19
Asterisk 13.14.0
FreePBX 13.0.192.8

We invoked the update process from SysAdmin Pro last evening at 17:35 and it is still in progress today at 16:10. The following processes are running:

# ps -ef 
UID        PID  PPID  C STIME TTY          TIME CMD
root         1     0  0 May04 ?        00:00:01 /sbin/init
root         2     0  0 May04 ?        00:00:00 [kthreadd]
root         3     2  0 May04 ?        00:00:00 [migration/0]
root         4     2  0 May04 ?        00:00:27 [ksoftirqd/0]
root         5     2  0 May04 ?        00:00:00 [stopper/0]
root         6     2  0 May04 ?        00:00:05 [watchdog/0]
root         7     2  0 May04 ?        00:08:18 [events/0]
root         8     2  0 May04 ?        00:00:00 [events/0]
root         9     2  0 May04 ?        00:00:00 [events_long/0]
root        10     2  0 May04 ?        00:00:00 [events_power_ef]
root        11     2  0 May04 ?        00:00:00 [cgroup]
root        12     2  0 May04 ?        00:00:00 [khelper]
root        13     2  0 May04 ?        00:00:00 [netns]
root        14     2  0 May04 ?        00:00:00 [async/mgr]
root        15     2  0 May04 ?        00:00:00 [pm]
root        16     2  0 May04 ?        00:00:13 [sync_supers]
root        17     2  0 May04 ?        00:00:14 [bdi-default]
root        18     2  0 May04 ?        00:00:00 [kintegrityd/0]
root        19     2  0 May04 ?        00:06:01 [kblockd/0]
root        20     2  0 May04 ?        00:00:00 [kacpid]
root        21     2  0 May04 ?        00:00:00 [kacpi_notify]
root        22     2  0 May04 ?        00:00:00 [kacpi_hotplug]
root        23     2  0 May04 ?        00:00:00 [ata_aux]
root        24     2  0 May04 ?        00:00:00 [ata_sff/0]
root        25     2  0 May04 ?        00:00:00 [ksuspend_usbd]
root        26     2  0 May04 ?        00:00:00 [khubd]
root        27     2  0 May04 ?        00:00:00 [kseriod]
root        28     2  0 May04 ?        00:00:00 [md/0]
root        29     2  0 May04 ?        00:00:00 [md_misc/0]
root        30     2  0 May04 ?        00:00:00 [linkwatch]
root        32     2  0 May04 ?        00:00:02 [khungtaskd]
root        33     2  0 May04 ?        00:04:57 [kswapd0]
root        34     2  0 May04 ?        00:00:00 [ksmd]
root        35     2  0 May04 ?        00:01:19 [khugepaged]
root        36     2  0 May04 ?        00:00:00 [aio/0]
root        37     2  0 May04 ?        00:00:00 [crypto/0]
root        44     2  0 May04 ?        00:00:00 [kthrotld/0]
root        46     2  0 May04 ?        00:00:00 [kpsmoused]
root        47     2  0 May04 ?        00:00:00 [usbhid_resumer]
root        48     2  0 May04 ?        00:00:00 [deferwq]
root        81     2  0 May04 ?        00:00:00 [kdmremove]
root        82     2  0 May04 ?        00:00:00 [kstriped]
root       112     2  0 May04 ?        00:00:01 [i915]
root       113     2  0 May04 ?        00:00:00 [i915-dp]
root       114     2  0 May04 ?        00:00:00 [i915-hangcheck]
root       228     2  0 May04 ?        00:00:00 [scsi_eh_0]
root       229     2  0 May04 ?        00:00:00 [scsi_eh_1]
root       303     2  0 May04 ?        00:00:19 [kdmflush]
root       305     2  0 May04 ?        00:00:00 [kdmflush]
root       323     2  0 May04 ?        00:01:25 [jbd2/dm-0-8]
root       324     2  0 May04 ?        00:00:00 [ext4-dio-unwrit]
root       400     1  0 May04 ?        00:00:00 /sbin/udevd -d
root       628     2  0 May04 ?        00:00:42 [kdmflush]
root       632     2  0 May04 ?        00:00:00 [kdmflush]
root       635     2  0 May04 ?        00:00:23 [kdmflush]
root       637     2  0 May04 ?        00:00:36 [kdmflush]
root       701     2  0 May04 ?        00:00:00 [jbd2/sda1-8]
root       702     2  0 May04 ?        00:00:00 [ext4-dio-unwrit]
root       703     2  0 May04 ?        00:00:00 [jbd2/dm-3-8]
root       704     2  0 May04 ?        00:00:00 [ext4-dio-unwrit]
root       705     2  0 May04 ?        00:02:54 [jbd2/dm-2-8]
root       706     2  0 May04 ?        00:00:00 [ext4-dio-unwrit]
root       707     2  0 May04 ?        00:02:53 [jbd2/dm-5-8]
root       708     2  0 May04 ?        00:00:00 [ext4-dio-unwrit]
root       709     2  0 May04 ?        00:02:26 [jbd2/dm-4-8]
root       710     2  0 May04 ?        00:00:00 [ext4-dio-unwrit]
root       746     2  0 May04 ?        00:01:00 [kauditd]
root       924     2  0 May04 ?        00:00:52 [flush-253:0]
root       925     2  0 May04 ?        00:07:30 [flush-253:2]
root       928     2  0 May04 ?        00:13:13 [flush-253:4]
root       929     2  0 May04 ?        00:00:48 [flush-253:5]
root      1136     1  0 May04 ?        00:04:51 auditd
root      1156     1  0 May04 ?        00:02:45 /sbin/rsyslogd -i /var/run/syslogd.pid
root      1211   400  0 May04 ?        00:00:00 /sbin/udevd -d
root      1212   400  0 May04 ?        00:00:00 /sbin/udevd -d
root      1301     1  0 May04 ?        00:00:00 mdadm --monitor --scan -f --pid-file=/
dbus      1311     1  0 May04 ?        00:00:00 dbus-daemon --system
avahi     1323     1  0 May04 ?        00:00:00 avahi-daemon: running [voinet09.local]
avahi     1324  1323  0 May04 ?        00:00:00 avahi-daemon: chroot helper
root      1355     1  0 May04 ?        00:00:00 /usr/sbin/acpid
68        1365     1  0 May04 ?        00:00:26 hald
root      1366  1365  0 May04 ?        00:00:00 hald-runner
root      1395  1366  0 May04 ?        00:00:00 hald-addon-input: Listening on /dev/in
68        1404  1366  0 May04 ?        00:00:00 hald-addon-acpi: listening on acpid so
nobody    1440     1  0 May04 ?        00:00:55 /usr/sbin/dnsmasq
root      1455     1  0 May04 ?        00:00:00 /usr/sbin/sshd
ntp       1473     1  0 May04 ?        00:00:22 ntpd -u ntp:ntp -p /var/run/ntpd.pid -
root      1519     1  0 May04 ?        00:00:00 /bin/sh /usr/bin/mysqld_safe --datadir
mysql     1633  1519  1 May04 ?        13:52:29 /usr/libexec/mysqld --basedir=/usr --d
root      1659     1  0 May04 ?        00:09:54 /usr/sbin/haveged -w 1024 -v 1
root      1737     1  0 May04 ?        00:00:17 /usr/libexec/postfix/master
postfix   1747  1737  0 May04 ?        00:00:08 qmgr -l -t fifo -u
root      1748     1  0 May04 ?        00:02:26 /usr/sbin/httpd
root      1795     1  0 May04 ?        00:05:42 crond
asterisk  1865     1  0 May04 ?        00:00:00 /bin/bash /opt/isymphony/server//start
asterisk  1877  1865  0 May04 ?        00:00:00 /bin/bash iSymphonyServer.sh start
asterisk  1881  1877  0 May04 ?        00:51:11 /usr/java/latest/bin/java -Djava.libra
uucp      1892     1  0 May04 ?        00:00:01 faxq
uucp      1899     1  0 May04 ?        00:01:21 hfaxd -i hylafax
root      1941     1  0 May04 ?        00:01:50 /usr/bin/perl /usr/libexec/webmin/mini
root      1950     1  0 May04 tty1     00:00:00 /sbin/mingetty /dev/tty1
root      1952     1  0 May04 tty2     00:00:00 /sbin/mingetty /dev/tty2
root      1955     1  0 May04 tty3     00:00:00 /sbin/mingetty /dev/tty3
root      1957     1  0 May04 tty4     00:00:00 /sbin/mingetty /dev/tty4
root      1959     1  0 May04 tty5     00:00:00 /sbin/mingetty /dev/tty5
root      1961     1  0 May04 tty6     00:00:00 /sbin/mingetty /dev/tty6
uucp      1965     1  0 May04 ?        00:03:47 /usr/sbin/faxgetty ttyIAX0
uucp      1968     1  0 May04 pts/0    00:12:33 /usr/bin/iaxmodem ttyIAX0
uucp      1971     1  0 May04 ?        00:00:14 /usr/sbin/faxgetty ttyIAX1
uucp      1974     1  0 May04 pts/1    00:00:46 /usr/bin/iaxmodem ttyIAX1
root      2063     2  0 May04 ?        00:00:00 [bluetooth]
root     10925     1  0 Jun01 ?        00:02:52 /usr/libexec/gam_server
root     11200     1  0 Jun01 ?        00:34:36 /usr/bin/python /usr/bin/fail2ban-serv
root     12863     1  0 Jun01 ?        00:00:00 incrond
root     14628     1  0 Jun01 ?        00:00:00 xinetd -stayalive -pidfile /var/run/xi
root     19451     1  0 May18 ?        00:00:00 /bin/sh /usr/sbin/safe_asterisk -U ast
asterisk 19454 19451  0 May18 ?        06:48:30 /usr/sbin/asterisk -f -U asterisk -G a
mongodb  20429     1  0 May17 ?        02:05:52 /usr/bin/mongod --quiet -f /etc/mongod
asterisk 21481     1  0 May04 ?        00:49:13 PM2 v2.4.6: God Daemon (/home/asterisk
asterisk 23582  1748  0 14:33 ?        00:00:04 /usr/sbin/httpd
asterisk 23585  1748  0 14:33 ?        00:00:04 /usr/sbin/httpd
asterisk 23586  1748  0 14:33 ?        00:00:01 /usr/sbin/httpd
asterisk 24310  1748  0 14:42 ?        00:00:02 /usr/sbin/httpd
asterisk 24311  1748  0 14:42 ?        00:00:01 /usr/sbin/httpd
asterisk 24312  1748  0 14:42 ?        00:00:01 /usr/sbin/httpd
asterisk 25278 21481  0 May17 ?        00:55:10 letschat                             
asterisk 26126  1748  0 15:07 ?        00:00:02 /usr/sbin/httpd
postfix  26469  1737  0 15:12 ?        00:00:00 pickup -l -t fifo -u
asterisk 27464  1748  0 15:28 ?        00:00:00 /usr/sbin/httpd
root     29865     2  0 16:04 ?        00:00:00 [flush-253:3]
root     29948 31796  4 16:04 pts/4    00:00:00 ps -ef
root     31275     1  0 Jun15 ?        00:00:00 /bin/sh -e -c exec su -s /bin/bash -c 
root     31276 31275  0 Jun15 ?        00:00:00 su -s /bin/bash -c stdbuf -oL -eL /usr
root     31277 31275  0 Jun15 ?        00:00:00 logger -t sangoma_pnp
asterisk 31278 31276  0 Jun15 ?        00:00:00 /usr/bin/python /usr/local/bin/pnp_ser
root     31783  1455  0 Jun16 ?        00:00:00 sshd: root@pts/2 
root     31785 31783  0 Jun16 pts/2    00:00:00 bash -c tmux  || bash -l || sh
root     31793 31785  0 Jun16 pts/2    00:00:00 tmux
root     31795     1  0 Jun16 ?        00:00:35 tmux
root     31796 31795  0 Jun16 pts/4    00:00:00 -bash
asterisk 32200 21481  0 08:43 ?        00:00:24 node /var/www/html/admin/modules/ucpno\

Long long is this supposed to take? Is there a problem? How do we proceed from here?

byrnejb · June 19, 2017, 12:46pm

This is what the sysadmin pro page shows when the upgrade log is displayed:

System Admin
Updates
Current Version   10.13.66-19
View Log
Your server can now be updated.
10.13.66-20
Upgrade in progress
This will upgrade your machine to version 10.13.66-20
Automatic Updates No

Update Log

Update currently in progress! Please wait until complete.

    2017-02-17 18:04:04: (10.13.66-18) Starting stage 6
    2017-02-17 18:04:05: (10.13.66-18) Stage 6 complete
    2017-02-17 18:04:05: (10.13.66-18) Upgrade script complete
    2017-02-17 18:04:07: (10.13.66-18) Upgrade process successfully completed!
    2017-04-10 20:51:54: (10.13.66-19) Requesting updates
    2017-04-10 20:51:55: (10.13.66-19) Processing update
    2017-04-10 20:51:55: (10.13.66-19) Now running 10.13.66-19 script
    2017-04-10 20:51:56: (10.13.66-19) Starting stage 1
    2017-04-10 21:03:44: (10.13.66-19) Stage 1 complete
    2017-04-10 21:03:45: (10.13.66-19) Starting stage 2
    2017-04-10 21:08:13: (10.13.66-19) Stage 2 complete
    2017-04-10 21:08:13: (10.13.66-19) Stage 3 complete
    2017-04-10 21:08:13: (10.13.66-19) Starting stage 4
    2017-04-10 21:10:14: (10.13.66-19) Stage 4 complete
    2017-04-10 21:10:14: (10.13.66-19) Starting stage 5
    2017-04-10 21:10:14: (10.13.66-19) Stage 5 complete
    2017-04-10 21:10:14: (10.13.66-19) Starting stage 6
    2017-04-10 21:10:15: (10.13.66-19) Stage 6 complete
    2017-04-10 21:10:15: (10.13.66-19) Upgrade script complete
    2017-04-10 21:10:17: (10.13.66-19) Upgrade process successfully completed!

The log says that the upgrade completed successfully but the system says that it is still at 10.13.66-19 and that the upgrade is still in progress. Also note the strange dates displayed in the log. The log seems to be displaying the previous update results but not the current. Is this intended behaviour?

Also, this system has been restarted since the upgrade completed and this event has changed nothing whatsoever with respect to the Sysadmin Pro Upgrade page display.

How is this problem dealt with?

lgaetz · June 19, 2017, 12:47pm

At the bash prompt run:

 /usr/sbin/sysadmin_update_system --unlock

byrnejb · June 19, 2017, 1:30pm

Thank you very much. That unlocks the upgrade in progress notice and the system now says that an upgrade to -20 is available again.

Now I need some help on how I discover why the first attempt failed and what I need do to prevent another failed attempt.

Marbled · June 19, 2017, 1:53pm

Hi!

You can run it manually if you want…

The script is here https://upgrades.freepbxdistro.org/stable/10.13.66/upgrade-10.13.66-20.sh

and the instructions are here Sangoma Documentation

I usually try to run them manually as I have not been always lucky when I ran them from System Admin Pro (ie I had the same problem you had…).

Good luck and have a nice day!

Nick

mvogel4949 · June 19, 2017, 2:25pm

I am having a similar issue as I am able to unlock an update but the update run either from the gui or root always hangs as seen below.

Marbled · June 19, 2017, 3:28pm

Hi!

I see a lot of warnings (and for some apps it is “normal”) but there doesn’t seem to be any actual errors in there, the error must be elsewhere…

Take this with a grain of salt though because while I am a programmer I am far from a C/C++ guru…

As to whether it is the same problem as the OP, only logs from both of you would say I think…

Is there anything different from stock in your install since this updates obviously runs OK on other installs?

Good luck and have a nice day!

Nick

byrnejb · June 19, 2017, 4:53pm

This is a standard FreePBX distor with updates and several commercial module addons, all from the FreePBX people. We have one customised /etc/asterisk/extensions_override_freepbx.conf file that provides for different ring tones based on the call origin. We have always updated through the SysAdminPro module and this time differs only in that it did not complete for some reason.

byrnejb · June 19, 2017, 5:25pm

Looking at /var/log/pbx/upgrade I find no entries whatsoever for the -20 upgrade attempt even though the messages window that open displayed the steps completing.

# ll  /var/log/pbx/upgrade
. . .
-rw-r--r-- 1 root root   1989 Feb 17 18:04 10.13.66-18
-rw-r--r-- 1 root root 286514 Feb 17 18:04 10.13.66-18.output
-rw-r--r-- 1 root root   1989 Apr 10 21:10 10.13.66-19
-rw-r--r-- 1 root root 220679 Apr 10 21:10 10.13.66-19.output
-rw-r--r-- 1 root root   1790 Nov 28  2016 10.13.66-2
-rw-r--r-- 1 root root  76450 Nov 28  2016 10.13.66-2.output
-rw-r--r-- 1 root root   1790 Nov 28  2016 10.13.66-3
-rw-r--r-- 1 root root  76450 Nov 28  2016 10.13.66-3.output
-rw-r--r-- 1 root root   1835 Nov 28  2016 10.13.66-4
. . .

Marbled · June 20, 2017, 12:39am

@byrnejb, can you try doing it manually this time?

Good luck and have a nice day!

Nick