Anyone Ever Experienced A Crash Where Asterisk Debug Output A Line With All Nulls
Home » 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
6 thoughts on - 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!
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.
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
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.
—
VGhhbmsgeW91Lg0KDQpBcHByZWNpYXRlIHRoZSBoZWxwIG9uIHRoaXMuDQoNCkRhbg0KDQpGcm9t OiBhc3Rlcmlzay11c2VycyA8YXN0ZXJpc2stdXNlcnMtYm91bmNlc0BsaXN0cy5kaWdpdW0uY29t PiBPbiBCZWhhbGYgT2YgSm9obiBSdW55b24NClNlbnQ6IFdlZG5lc2RheSwgQXVndXN0IDE0LCAy MDE5IDEwOjUxIEFNDQpUbzogQXN0ZXJpc2sgVXNlcnMgTWFpbGluZyBMaXN0IC0gTm9uLUNvbW1l cmNpYWwgRGlzY3Vzc2lvbiA8YXN0ZXJpc2stdXNlcnNAbGlzdHMuZGlnaXVtLmNvbT4NClN1Ympl Y3Q6IFJlOiBbYXN0ZXJpc2stdXNlcnNdIEFueW9uZSBldmVyIGV4cGVyaWVuY2VkIGEgY3Jhc2gg d2hlcmUgQXN0ZXJpc2sgZGVidWcgb3V0cHV0IGEgbGluZSB3aXRoIGFsbCBudWxscw0KDQpBZ3Jl ZSB3aXRoIE1pY2hhZWwsIHRoaXMgc291bmRzIGxpa2UgYW4gT1MgY3Jhc2ggdG8gbWUuIEdpdmVu IHRoYXQgeW91J3JlIG5vdCBzZWVpbmcgYW55dGhpbmcgaW4gdGhlIGxvZ3MsIGl0J3MgbGlrZWx5
IHRoYXQgYnkgdGhlIHRpbWUgdGhlIGNyYXNoIG9jY3VycywgdGhlIGtlcm5lbCBpcyB1bmFibGUg dG8gd3JpdGUgdG8gZGlzaywgc28gdGhlIG9ubHkgcmVhbCB3YXkgdG8gZ2V0IGluZm8gaXMgdG8g YmUgbG9va2luZyBhdCB0aGUgY29uc29sZSB3aGVuIGl0IGNyYXNoZXMuIFNlZSBhbHNvOiBodHRw czovL2hlbHAudWJ1bnR1LmNvbS9jb21tdW5pdHkvRGVidWdnaW5nU3lzdGVtQ3Jhc2gNClRoZSBp bml0aWFsIHNsb3duZXNzIGlzIGxpa2VseSBkdWUgZWl0aGVyIHRvIGNhY2hpbmcgb24gbGF0ZXIg cmVzdGFydHMsIG9yIHRvIGZzY2suDQoNCk9uIFdlZCwgMTQgQXVnIDIwMTkgYXQgMTA6MjMsIE1p Y2hhZWwgTWFpZXIgPG0xMjc4NDY4QG1haWxib3gub3JnPG1haWx0bzptMTI3ODQ2OEBtYWlsYm94
Lm9yZz4+IHdyb3RlOg0KT24gMTQuMDguMTkgYXQgMTY6MjYgRGFuIENyb3BwIHdyb3RlOg0KPiBX
ZSBoYXZlIGEgY3VzdG9tZXIgd2hlcmUgdGhlaXIgVk0gcnVubmluZyBBc3RlcmlzayBhcHBlYXJz IHRvIGhhdmUgY3Jhc2hlZC4gIEZvcnR1bmF0ZWx5LCB3ZSBoYWQgc29tZSBkZWJ1Z2dpbmcgZW5h YmxlZC4NCj4gVGhlIGFzdGVyaXNrIG1lc3NhZ2VzIGZpbGUgaGFzIHRoaXMuLi4gKGluIG5vdGVw YWQrIHRoZSBibGFuayBsaW5lIGluIHRoZSBtaWRkbGUgaXMgYWxsIFtOVUxdW05VTF0gW05VTF1b TlVMXS4uLi4pDQo+DQo+IFswOC8xMiAxNTozMDo1NS44ODBdIFZFUkJPU0VbNjkyMF0gYXBwX21p eG1vbml0b3IuYzogQmVnaW4gTWl4TW9uaXRvciBSZWNvcmRpbmcgQ0JSZWMvSVNfX2EzN2FlMDA0
LWM3ODAtNGM3Zi04OGE5LWEwNDQwMmYwYWI0ZS0wMDAwZTcwZg0KPiBbMDgvMTIgMTU6MzA6NTUu ODgxXSBWRVJCT1NFWzY5MjFdIGJyaWRnZV9jaGFubmVsLmM6IENoYW5uZWwgQ0JSZWMvSVNfX2Ez N2FlMDA0LWM3ODAtNGM3Zi04OGE5LWEwNDQwMmYwYWI0ZS0wMDAwZTcwZiBqb2luZWQgJ3NvZnRt aXgnIGJhc2UtYnJpZGdlIDwyMzM0MGJjYS02ODIzLTRjNzAtYTM5NS1lM2IwOTJhZWI2NzE+DQo+
DQo+IFswOC8xMiAxNTozMzowMi44ODddIEFzdGVyaXNrIDE2LjIuMSBidWlsdCBieSByb290IEAg c3ctZ2VuZXNpcy1idWlsZDQgb24gYSB4ODZfNjQgcnVubmluZyBMaW51eCBvbiAyMDE5LTA0LTA0
IDEzOjQxOjE1IFVUQw0KDQpEaWQgSSBnZXQgaXQgY29ycmVjdGx5OiB0aGUgbGFzdCBsaW5lIGlu IHRoZSBsb2cgYmVmb3JlIGFzdGVyaXNrIHN0YXJ0cyBhZ2FpbiBhZnRlciB0aGUgcmVib290IGlz IHRoZSBbbnVsXS1saW5lPyBJZiBzbywgYXJlIHlvdSBwcm9iYWJseSB1c2luZyBleHQ0IG9yIG1h eWJlIHJlaXNlcmZzPyBJIGtub3cgb2YgdGhpcyBwcm9ibGVtIGlmIHRoZSBtYWNoaW5lIGNyYXNo ZXMsIG9wZW4gZmlsZXMgY2FuIGVuZCB1cA0KbGlrZSBkZXNjcmliZWQuIEFGQUlLIGl0J3MgYSBm aWxlIHN5c3RlbSBidWchDQoNCj4gV2UgYWxzbyBoYWQgZGVidWdnaW5nIGVuYWJsZWQgYW5kIHRo aW5ncyB3ZXJlIG91dHB1dCB0byBvdXIgZGVidWcgZmlsZSBmb3IgMTcgbW9yZSBzZWNvbmRzLi4u Lg0KPiBUaGUgYmxhbmsgbGluZSBpbiBteSBlLW1haWwgaXMgb25jZSBhZ2FpbiBhIGxpbmUgd2l0
aCBhbGwgW05VTH0uLi4gKGluIG5vdGVwYWQrIHRoZSBibGFuayBsaW5lIGluIHRoZSBtaWRkbGUg aXMgYWxsIFtOVUxdW05VTF0gW05VTF1bTlVMXS4uLi4pDQo+DQo+IFswOC8xMiAxNTozMToxMi43
NzZdIERFQlVHWzY3ODFdIGF1ZGlvaG9vay5jOiBSZWFkIGZhY3RvcnkgMHg3ZjA3OTM4OWJmZjgg YW5kIHdyaXRlIGZhY3RvcnkgMHg3ZjA3OTM4OWNhMzggYm90aCBmYWlsIHRvIHByb3ZpZGUgMTYw IHNhbXBsZXMNCj4gWzA4LzEyIDE1OjMxOjEyLjc3N10gREVCVUdbNjcwOV0gYXVkaW9ob29rLmM6
IEZhaWxlZCB0byBnZXQgMTYwIHNhbXBsZXMgZnJvbSByZWFkIGZhY3RvcnkgMHg3ZjA3OTM3MDY2
ZDgNCj4gWzA4LzEyIDE1OjMxOjEyLjc3N10gREVCVUdbNjcwOV0gYXVkaW9ob29rLmM6IFJlYWQg ZmFjdG9yeSAweDdmMDc5MzcwNjZkOCBhbmQgd3JpdGUgZmFjdG9yeSAweDdmMDc5MzcwNzExOCBi b3RoIGZhaWwgdG8gcHJvdmlkZSAxNjAgc2FtcGxlcw0KPiAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAg ICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgICAgWzA4
LzEyIDE1OjMzOjAyLjkxNV0gQXN0ZXJpc2sgMTYuMi4xIGJ1aWx0IGJ5IHJvb3QgQCBzdy1nZW5l c2lzLWJ1aWxkNCBvbiBhIHg4Nl82NCBydW5uaW5nIExpbnV4IG9uIDIwMTktMDQtMDQgMTM6NDE6
MTUgVVRDDQo+IFtBdWcgMTIgMTU6MzM6MDJdIERFQlVHWzEzODVdIGNvbmZpZy5jOiBQYXJzaW5n IC9ldGMvaXNzL2FzdGVyaXNrL2xvZ2dlci5jb25mDQo+DQo+DQo+DQo+IEkgYmVsaWV2ZSB0aGlz IHdhcyBiYWQgZW5vdWdoIHRoYXQgVWJ1bnR1IGFjdHVhbGx5IGNyYXNoZWQsIGJ1dCB0aGVyZSBp cyBub3RoaW5nIGluIHRoZSBzeXNsb2cgaW5kaWNhdGluZyBhbnl0aGluZyB1bnRpbCAxNTozMjo0
MiB3aGVyZSBpdCBhcHBlYXJzIExpbnV4IGlzIHN0YXJ0aW5nIHVwLg0KPg0KPg0KPiBBZnRlciB0
aGlzIHNpdHVhdGlvbiBoYXBwZW5zLCBldmVyeSB0aW1lIEFzdGVyaXNrIHN0YXJ0cyB1cCwgaXQg d2FzIHRha2luZyBzaWduaWZpY2FudGx5IGxvbmdlciB0byBsb2FkLiAgTm9ybWFsbHkgMS0yIHNl Y29uZHMsIGJlY2FtZSAyNi0yOCBzZWNvbmRzLg0KPiBbMDgvMTIgMTU6MzM6MDMuMjQwXSBOT1RJ
Q0VbMTM4NV0gbG9hZGVyLmM6IDI4NiBtb2R1bGVzIHdpbGwgYmUgbG9hZGVkLg0KPiBbMDgvMTIg MTU6MzM6MjMuODQ0XSBWRVJCT1NFWzEzODVdIGxvYWRlci5jOiBMb2FkaW5nIGV4dGNvbmZpZy4N
Cj4NCj4NCj4gTG9hZGluZyB0aGUgbW9kdWxlcyBpcyB0YWtpbmcgMjAgc2Vjb25kcyBhZnRlciB0
aGlzIGluY2lkZW50IG9jY3VycmVkLiAgTG9va2luZyBhdCB0aGUgZGVidWcgbG9ncywgSSBzZWUg dGhlIG1vZHVsZXMgbG9hZGluZyBsb2FkZXIuYyBQQVNTLiAgVGhlcmUgYWxsIHNlZW0gdG8gbG9h ZCBmaW5lLCBqdXN0IG11Y2ggc2xvd2VyIHRoYW4gaXQgd2FzIHByZXZpb3VzbHkuDQoNCk1heWJl IGJlY2F1c2UgdGhlIG1hY2hpbmUgaXMgcGVyZm9ybWluZyBhIGZpbGUgc3lzdGVtIGNoZWNrIG9u IHNvbWUgb3RoZXIgcGFydGl0aW9ucyBpbiBwYXJhbGxlbCBhbmQgaXQncyBzbG93ZWQgZG93biB0
aGVyZWZvcmU/DQoNCg0KUmVnYXJkcw0KTWljaGFlbA0KLS0NCl9fX19fX19fX19fX19fX19fX19f X19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fX19fXw0KLS0gQmFu ZHdpZHRoIGFuZCBDb2xvY2F0aW9uIFByb3ZpZGVkIGJ5IGh0dHA6Ly93d3cuYXBpLWRpZ2l0YWwu Y29tIC0tDQoNCkNoZWNrIG91dCB0aGUgbmV3IEFzdGVyaXNrIGNvbW11bml0eSBmb3J1bSBhdDog aHR0cHM6Ly9jb21tdW5pdHkuYXN0ZXJpc2sub3JnLw0KDQpOZXcgdG8gQXN0ZXJpc2s/IFN0YXJ0
IGhlcmU6DQogICAgICBodHRwczovL3dpa2kuYXN0ZXJpc2sub3JnL3dpa2kvZGlzcGxheS9BU1Qv R2V0dGluZytTdGFydGVkDQoNCmFzdGVyaXNrLXVzZXJzIG1haWxpbmcgbGlzdA0KVG8gVU5TVUJT
Q1JJQkUgb3IgdXBkYXRlIG9wdGlvbnMgdmlzaXQ6DQogICBodHRwOi8vbGlzdHMuZGlnaXVtLmNv bS9tYWlsbWFuL2xpc3RpbmZvL2FzdGVyaXNrLXVzZXJzDQoNCg0KLS0NClJlZ2FyZHMsDQpKb2hu IFJ1bnlvbg0KU2ltcGx5IE5VQw0KNTEyLTc2Ni0wNDAxIHgxMTEwDQo0OTUgUm91bmQgUm9jayBX
ZXN0IERyLCBSb3VuZCBSb2NrLCBUWCA3ODY4MQ0K
Well, it was just speculation. Is it even now reproducible after the 3. or even later reboot? I would try to log in via ssh as fast as possible
(or directly via a shell) and try to find the responsible process. Try to examine the IO.
If the machine is shut down manually, did it perform a correct shutdown (= all file systems have been correctly unmounted and all processes have been stopped before unmounting)?
Is the startup slow even if it’s done w/o reboot before?
Regards Michael
—
I have been told they went to an earlier snapshot of the VM and are running on that one now so we no longer have access to the VM from the state it was in.
The startup on their old snapshot VM is taking about 2 seconds for asterisk to load the configuration files.
Someone finally admitted to me the VM that crashed was missing over 200 package updates. At this point, that’s what we are chalking it up to.
Have a great day!
Dan
—–Original Message—