asterisk users - Aug 2019 - 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>

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

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>

> 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.