Dan Cropp
2019-Aug-14 14:26 UTC
[asterisk-users] Anyone ever experienced a crash where Asterisk debug output a line with all nulls
We have a customer where their VM running Asterisk appears to have crashed.
Fortunately, we had some debugging enabled.
The asterisk messages file has this... (in notepad+ the blank line in the middle
is all [NUL][NUL] [NUL][NUL]....)
[08/12 15:30:55.880] VERBOSE[6920] app_mixmonitor.c: Begin MixMonitor Recording
CBRec/IS__a37ae004-c780-4c7f-88a9-a04402f0ab4e-0000e70f
[08/12 15:30:55.881] VERBOSE[6921] bridge_channel.c: Channel
CBRec/IS__a37ae004-c780-4c7f-88a9-a04402f0ab4e-0000e70f joined 'softmix'
base-bridge <23340bca-6823-4c70-a395-e3b092aeb671>
[08/12 15:33:02.887] Asterisk 16.2.1 built by root @ sw-genesis-build4 on a
x86_64 running Linux on 2019-04-04 13:41:15 UTC
We also had debugging enabled and things were output to our debug file for 17
more seconds....
The blank line in my e-mail is once again a line with all [NUL}... (in notepad+
the blank line in the middle is all [NUL][NUL] [NUL][NUL]....)
[08/12 15:31:12.776] DEBUG[6781] audiohook.c: Read factory 0x7f079389bff8 and
write factory 0x7f079389ca38 both fail to provide 160 samples
[08/12 15:31:12.777] DEBUG[6709] audiohook.c: Failed to get 160 samples from
read factory 0x7f07937066d8
[08/12 15:31:12.777] DEBUG[6709] audiohook.c: Read factory 0x7f07937066d8 and
write factory 0x7f0793707118 both fail to provide 160 samples
[08/12 15:33:02.915] Asterisk 16.2.1 built by root @ sw-genesis-build4 on a
x86_64 running Linux on 2019-04-04 13:41:15 UTC
[Aug 12 15:33:02] DEBUG[1385] config.c: Parsing /etc/iss/asterisk/logger.conf
I believe this was bad enough that Ubuntu actually crashed, but there is nothing
in the syslog indicating anything until 15:32:42 where it appears Linux is
starting up.
After this situation happens, every time Asterisk starts up, it was taking
significantly longer to load. Normally 1-2 seconds, became 26-28 seconds.
[08/12 15:33:03.240] NOTICE[1385] loader.c: 286 modules will be loaded.
[08/12 15:33:23.844] VERBOSE[1385] loader.c: Loading extconfig.
Loading the modules is taking 20 seconds after this incident occurred. Looking
at the debug logs, I see the modules loading loader.c PASS. There all seem to
load fine, just much slower than it was previously.
Any suggestions on where to look for a cause of things running slow after this?
Dan
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://lists.digium.com/pipermail/asterisk-users/attachments/20190814/ed50cbfc/attachment.html>
Michael Maier
2019-Aug-14 15:21 UTC
[asterisk-users] Anyone ever experienced a crash where Asterisk debug output a line with all nulls
On 14.08.19 at 16:26 Dan Cropp wrote:> We have a customer where their VM running Asterisk appears to have crashed. Fortunately, we had some debugging enabled. > The asterisk messages file has this... (in notepad+ the blank line in the middle is all [NUL][NUL] [NUL][NUL]....) > > [08/12 15:30:55.880] VERBOSE[6920] app_mixmonitor.c: Begin MixMonitor Recording CBRec/IS__a37ae004-c780-4c7f-88a9-a04402f0ab4e-0000e70f > [08/12 15:30:55.881] VERBOSE[6921] bridge_channel.c: Channel CBRec/IS__a37ae004-c780-4c7f-88a9-a04402f0ab4e-0000e70f joined 'softmix' base-bridge <23340bca-6823-4c70-a395-e3b092aeb671> > > [08/12 15:33:02.887] Asterisk 16.2.1 built by root @ sw-genesis-build4 on a x86_64 running Linux on 2019-04-04 13:41:15 UTCDid I get it correctly: the last line in the log before asterisk starts again after the reboot is the [nul]-line? If so, are you probably using ext4 or maybe reiserfs? I know of this problem if the machine crashes, open files can end up like described. AFAIK it's a file system bug!> We also had debugging enabled and things were output to our debug file for 17 more seconds.... > The blank line in my e-mail is once again a line with all [NUL}... (in notepad+ the blank line in the middle is all [NUL][NUL] [NUL][NUL]....) > > [08/12 15:31:12.776] DEBUG[6781] audiohook.c: Read factory 0x7f079389bff8 and write factory 0x7f079389ca38 both fail to provide 160 samples > [08/12 15:31:12.777] DEBUG[6709] audiohook.c: Failed to get 160 samples from read factory 0x7f07937066d8 > [08/12 15:31:12.777] DEBUG[6709] audiohook.c: Read factory 0x7f07937066d8 and write factory 0x7f0793707118 both fail to provide 160 samples > [08/12 15:33:02.915] Asterisk 16.2.1 built by root @ sw-genesis-build4 on a x86_64 running Linux on 2019-04-04 13:41:15 UTC > [Aug 12 15:33:02] DEBUG[1385] config.c: Parsing /etc/iss/asterisk/logger.conf > > > > I believe this was bad enough that Ubuntu actually crashed, but there is nothing in the syslog indicating anything until 15:32:42 where it appears Linux is starting up. > > > After this situation happens, every time Asterisk starts up, it was taking significantly longer to load. Normally 1-2 seconds, became 26-28 seconds. > [08/12 15:33:03.240] NOTICE[1385] loader.c: 286 modules will be loaded. > [08/12 15:33:23.844] VERBOSE[1385] loader.c: Loading extconfig. > > > Loading the modules is taking 20 seconds after this incident occurred. Looking at the debug logs, I see the modules loading loader.c PASS. There all seem to load fine, just much slower than it was previously.Maybe because the machine is performing a file system check on some other partitions in parallel and it's slowed down therefore? Regards Michael
John Runyon
2019-Aug-14 15:51 UTC
[asterisk-users] Anyone ever experienced a crash where Asterisk debug output a line with all nulls
Agree with Michael, this sounds like an OS crash to me. Given that you're not seeing anything in the logs, it's likely that by the time the crash occurs, the kernel is unable to write to disk, so the only real way to get info is to be looking at the console when it crashes. See also: https://help.ubuntu.com/community/DebuggingSystemCrash The initial slowness is likely due either to caching on later restarts, or to fsck. On Wed, 14 Aug 2019 at 10:23, Michael Maier <m1278468 at mailbox.org> wrote:> On 14.08.19 at 16:26 Dan Cropp wrote: > > We have a customer where their VM running Asterisk appears to have > crashed. Fortunately, we had some debugging enabled. > > The asterisk messages file has this... (in notepad+ the blank line in > the middle is all [NUL][NUL] [NUL][NUL]....) > > > > [08/12 15:30:55.880] VERBOSE[6920] app_mixmonitor.c: Begin MixMonitor > Recording CBRec/IS__a37ae004-c780-4c7f-88a9-a04402f0ab4e-0000e70f > > [08/12 15:30:55.881] VERBOSE[6921] bridge_channel.c: Channel > CBRec/IS__a37ae004-c780-4c7f-88a9-a04402f0ab4e-0000e70f joined 'softmix' > base-bridge <23340bca-6823-4c70-a395-e3b092aeb671> > > > > > > > > > > > > [08/12 15:33:02.887] Asterisk 16.2.1 built by root @ sw-genesis-build4 > on a x86_64 running Linux on 2019-04-04 13:41:15 UTC > > Did I get it correctly: the last line in the log before asterisk starts > again after the reboot is the [nul]-line? If so, are you probably using > ext4 or maybe reiserfs? I know of this problem if the machine crashes, open > files can end up > like described. AFAIK it's a file system bug! > > > We also had debugging enabled and things were output to our debug file > for 17 more seconds.... > > The blank line in my e-mail is once again a line with all [NUL}... (in > notepad+ the blank line in the middle is all [NUL][NUL] [NUL][NUL]....) > > > > [08/12 15:31:12.776] DEBUG[6781] audiohook.c: Read factory > 0x7f079389bff8 and write factory 0x7f079389ca38 both fail to provide 160 > samples > > [08/12 15:31:12.777] DEBUG[6709] audiohook.c: Failed to get 160 samples > from read factory 0x7f07937066d8 > > [08/12 15:31:12.777] DEBUG[6709] audiohook.c: Read factory > 0x7f07937066d8 and write factory 0x7f0793707118 both fail to provide 160 > samples > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > [08/12 > 15:33:02.915] Asterisk 16.2.1 built by root @ sw-genesis-build4 on a x86_64 > running Linux on 2019-04-04 13:41:15 UTC > > [Aug 12 15:33:02] DEBUG[1385] config.c: Parsing > /etc/iss/asterisk/logger.conf > > > > > > > > I believe this was bad enough that Ubuntu actually crashed, but there is > nothing in the syslog indicating anything until 15:32:42 where it appears > Linux is starting up. > > > > > > After this situation happens, every time Asterisk starts up, it was > taking significantly longer to load. Normally 1-2 seconds, became 26-28 > seconds. > > [08/12 15:33:03.240] NOTICE[1385] loader.c: 286 modules will be loaded. > > [08/12 15:33:23.844] VERBOSE[1385] loader.c: Loading extconfig. > > > > > > Loading the modules is taking 20 seconds after this incident occurred. > Looking at the debug logs, I see the modules loading loader.c PASS. There > all seem to load fine, just much slower than it was previously. > > Maybe because the machine is performing a file system check on some other > partitions in parallel and it's slowed down therefore? > > > Regards > Michael > -- > _____________________________________________________________________ > -- Bandwidth and Colocation Provided by http://www.api-digital.com -- > > Check out the new Asterisk community forum at: > https://community.asterisk.org/ > > New to Asterisk? Start here: > https://wiki.asterisk.org/wiki/display/AST/Getting+Started > > asterisk-users mailing list > To UNSUBSCRIBE or update options visit: > http://lists.digium.com/mailman/listinfo/asterisk-users-- Regards, John Runyon Simply NUC 512-766-0401 x1110 495 Round Rock West Dr, Round Rock, TX 78681 -------------- next part -------------- An HTML attachment was scrubbed... URL: <http://lists.digium.com/pipermail/asterisk-users/attachments/20190814/8b498005/attachment.html>
Dan Cropp
2019-Aug-14 16:12 UTC
[asterisk-users] Anyone ever experienced a crash where Asterisk debug output a line with all nulls
> Did I get it correctly: the last line in the log before asterisk starts again after the reboot is the [nul]-line? If so, are you probably using ext4 or maybe reiserfs? I know of this problem if the machine crashes, open files can end up like described. AFAIK it's a file system bug!Yes, the last line in in the log before asterisk starts again after the reboot is the [nul]-line. I believe you are right about the system using ext4 and the [nul]-line problem> Maybe because the machine is performing a file system check on some other partitions in parallel and it's slowed down therefore?Wouldn't /var/log/syslog show something like this if it's happening in parallel? syslog has items before asterisk is starting, but once the Asterisk log files show it's starting to completed, /var/log/syslog has nothing. Syslog has nothing for about 10 minutes after that. The strange thing is the customer did a manual restart of Ubuntu 20 minutes later and the same slow startup time happened.