JAERO shuts down after a couple of minutes when running with libacars 1.2.0 about libacars HOT 40 CLOSED

Not a whole lot of information...

Do you get any error messages? What do they say?

from libacars.

Hi Tomasz, I have no error messages, the JAERO program shuts down normally ..as though the "Exit" control has been selected. The program runs for 1-3 minutes approx. before closing down, the log shows the data and I could not see any particular repeated msg at the time of shutdown. Would a copy of the Log be of any use to you? Or some other detail?
Sorry....
Dave

from libacars.

The ACARS file itself would not be of much use. I'll try to reproduce this when I'll have access to a Win10 machine. Meanwhile, can you please try to copy both libacars.dll and zlib1.dll from the new libacars release into the JAERO directory? In theory, libacars should run correctly with zlib1.dll which is bundled with JAERO, but in theory theory and practice are the same thing, while in practice they often are not.

from libacars.

I have tried the prog with both new files and also with the new libacars and the "old" zlib1 it does not make any difference,the prog still shuts itself down after a short time. I also tried setting the RX to a vacant(no signal) frequency .....the prog runs and runs..! As soon as I tune a active frequency the prog shuts itself down after a couple of minutes.
Dave

from libacars.

A couple of hours straight with JAERO 1.0.4.10 and libacars.dll 1.2.0 on L-band 10500 today - no issues.

Initially I suspected that there might be some problem with handling compressed MIAM messages, but no, they seem to be decoded OK. I needed about an hour to catch one though (they are quite rare on L-band).

So I'm about to close this issue now, but if anybody is able to reproduce this reliably and provide me with more clues, then we might reopen it.

from libacars.

Szpajder. I need help I'm having same problem with jaero with new libacar 1.2.0 shuth itself after 2 minutes .I replace with old libacard works for hours I'm using windows 10 with all updates everything else run good.
Thank you

from libacars.

As I mentioned before, so far I was unable to reproduce this problem, so I can't even start troubleshooting it...

Try launching cmd.exe (Start -> Run -> cmd.exe), then go to the directory where JAERO is installed (probably cd c:\program files\JAERO or similar) and run JAERO from there by typing .\JAERO? When the program exits, maybe there will be some error message printed to the cmd window?

from libacars.

from libacars.

from libacars.

Unfortunately this doesn't help much. That's the problem with Windows - it's really hard to troubleshoot such issues. Maybe compiling and running JAERO and libacars with debugging enabled could shed some light on this.

from libacars.

@tonypaulino another idea - if the problem occurs so often, could you then record the sound? You could then repeat the decoding of the fragment that caused the program to terminate to see if the problem occurs every time. If so, please share the recording - I will check if I can reproduce the problem. Thank you in advance.

from libacars.

from libacars.

from libacars.

from libacars.

from libacars.

from libacars.

from libacars.

from libacars.

@G7gqw, are you able to take an audio recording which crashes the program reliably?

from libacars.

https://mega.nz/#!9dEwyQCL!0kufEBqbCd9fozkOqAJ4MNO2SIiy8rw_SgPzGnm3SFo
Hi Tomasz, try this ,shuts down after approx. 40 seconds, just after a "MIAM single transfer" data msg.

from libacars.

I see this one on the middle channel (repeated once):

15:56:55 07-08-19 AES:76CDAB GES:90 2 .9V-SMK ! MA A

	T.0&HDeF/icra;b]orzEk)OQ|

	MIAM Single Transfer:
	 MIAM CORE Ack, version 1:
	  PDU Length: 20
	  Aircraft ID: .9V-SMK
	  Msg ACK num: 93
	  Transfer result: ack

The next message after the first occurrence is:

15:56:57 07-08-19 AES:A2B8DB GES:90 2 .N2748U ! H1 Q

	- #MD2,340M46.NESIL,262023,340M44.LAMSA,262023,340M44.EDISI,248033,340M42.TOMBI,242040,340M40.IDAKU,228060,340M37.SOLIN,226049,340M36.DEMOV,226049,340M36.RIMON,222045,340M36.RW12,222045,340M36/WD300,N68000W020000,338043.- #MDN67000W010000,296021.N64000E000000,222021.ROGLO,160012.ARTOR,242024.ELVIX,238080.KOLOB,240076.PEPOX,250065.BAREX,258053.KELEL,256041.KEKED,264039.NARKA,266031.NEPOT,270028.LAMIT,280015.TIMUR,286011.ADORU,208009.ATVE- #MDP,272009.EKI,272009.YAYLA,114007.KUDAK,030007.KULAR,032007.NESIL,292015.LAMSA,292015.EDISI,266018.TOMBI,262022.IDAKU,234048.SOLIN,232044.DEMOV,232044.RIMON,232042.RW12,232042/WD240,N68000W020000,346041.N67000W010000- #MD,304024.N64000E000000,216021.ROGLO,158011.ARTOR,234017.ELVIX,236051.KOLOB,244054.PEPOX,238043.BAREX,248042.KELEL,248033.KEKED,256031.NARKA,258026.NEPOT,262025.LAMIT,264022.TIMUR,256016.ADORU,278004.ATVEP,324007.EKI,- #MD322007.YAYLA,262005.KUDAK,014009.KULAR,016009.NESIL,340013.LAMSA,340013.EDISI,330012.TOMBI,316013.IDAKU,260017.SOLIN,244029.DEMOV,244029.RIMON,236031.RW12,238031/DD300232042.240238031.180244020.100306005:,,,,/CB3001- #MD92027.240194013.180184013.1001880166B17

and the next one after the second occurence is:

15:50:44 07-08-19 AES:8963D5 GES:90 2 .A6-EPF ! H1 J

	- #T0@00000U000000BLR0565DXB190807-1027#SBAGGAGE BELT 11#TBAGGAGE BELT 11

On the third channel I see this one:

16:07:24 07-08-19 AES:461F48 GES:90 2 .OH-LWA ! MA J

	T.0&HDeF/l,"i9NON%zL>r;e|

	MIAM Single Transfer:
	 MIAM CORE Ack, version 1:
	  PDU Length: 20
	  Aircraft ID: .OH-LWA
	  Msg ACK num: 58
	  Transfer result: ack

and this one comes next:

16:07:35 07-08-19 AES:3C70C1 GES:90 2 .D-ALFA ! AA S

	/PIKCPYA.AT1.D-ALFA2229BA1DD53C62C9A73822F8001F99

	FANS-1/A CPDLC Message:
	 CPDLC Uplink Message:
	  Header:
	   Msg ID: 4
	   Timestamp: 10:27:40
	  Message data:
	   AT [time] CONTACT [icaounitname] [frequency]
	    Time: 10:39
	    Facility Name: EISN
	    Facility function: center
	    VHF: 120.040 MHz

So still no luck from my side - everything runs fine.

It might be that the bug is somewhere else in JAERO code, not necessarily in libacars. It's just libacars triggering it in a non-deterministic way (depending on the memory layout, different versions of the libraries present in the system, etc).

from libacars.

Hi Tomasz, thanks for trying,we all appreciate your hard work and time, maybe it will sort out in any future updates to JAERO/libacars.
Cheers
Dave
G7gqw

from libacars.

Whoops sorry ..hit the wrong button..

from libacars.

You can try version 1.3.0, released today, if it makes any difference. I doubt this, but... never say never.

from libacars.

Tried v1.3.0, still shuts down after a short time, I have just noticed that an acars.log is saved but the plane.log isn't unless I close JAERO before it crashes. Not sure if this is significant....thanks for your help and time.
Cheers
Dave

from libacars.

extra info....when JAERO is restarted after a "crash" there is no sign of the acars.log data that has been recorded to file showing in the "acars" window, shows up ok if the prog is terminated before it "crashes" and then restarted..hope this helps
Cheers
Dave

from libacars.

I have just noticed that an acars.log is saved but the plane.log isn't unless I close JAERO before it crashes.

This is expected, because the acars.log file is synced to disk after every ACARS message. This makes it easier to follow the file with "tail" program, as it grows. What is plane.log file? I don't have such a thing.

when JAERO is restarted after a "crash" there is no sign of the acars.log data that has been recorded to file showing in the "acars" window, shows up ok if the prog is terminated before it "crashes" and then restarted

The whole contents of the acars window is saved into JAERO settings file on clean exit and restored from this file on next startup. When there is no clean exit, the contents does not get saved. This is why you don't get recent content in this window after a crash.

from libacars.

Understood about the acars.log, my bad on the "Plane.Log" , I should have written "Plane Log" and was referring to the window that opens via the button between "settings" and "audio mute"

from libacars.

I think there are two separate problems here.

1. I updated my build system and compiled, JAERO, libarcs (v1.3.0), libogg, libvorbis and libcorrect with the new build system. When I played a message through JAERO that used la_acars_decode_apps in libacars, JAERO didn't crash. However, when I used the compiled binaries in the assets of the release ( https://github.com/szpajder/libacars/releases/download/v1.3.0/libacars-1.3.0-win64.zip ) it did crash for me when la_acars_decode_apps was called. So I think that's a incompatibility problem with the different build environments. I am using "gcc.exe (Rev2, Built by MSYS2 project) 9.2.0" at the moment on Windows.

2. The other issue seems to be in the function closeEvent in the PlaneLog class of JAERO. "event->accept();" is called rather than "event->ignore();". This can cause JAERO to crash when the plane log window is opened, then closed, then opened again and scrolling through the log items using the vertical scrollbar. I have fixed that bug and have pushed it to the repo. However I have changed the .pro file a little so everything compiles properly on my current setup.

For the next release of JAERO I'll include a precompiled shared library of the latest libarcs using the same build environment that will build JAERO as well as the bug fix for issue 2. However, issue 1 might become a problem again in the future when newer versions of libarcs are released.

from libacars.

Thank you so much for yours and Tomasz time and energy on this,looking forward to the next release,still enjoying voice decoding on the current version, great s/w from you both.

from libacars.

Thanks @jontio for your input on this topic.

I build binary releases for Windows by cross-compiling libacars under Linux using x86_64-w64-mingw32 as a target architecture. If memory serves me well, the last release has been built with gcc 9.1.0. However the gcc different probably is not (and should not) be the root cause of this problem. As I mentioned, I did a couple of hours of tests using binary packages of JAERO 1.0.4.10 and libacars 1.3.0 under Windows 10, both with L-band and C-band signals and so far I was unable to reproduce this problem. So it must have something to do with the environment the program is being run in (like versions of some system DLLs in Windows, etc).

How do you know that the crash occured in la_acars_decode_apps routine? Did you get any meaningful traceback or the like? If i saw one, maybe I could fix the issue, but so far no one has been able to provide it to me.

from libacars.

Hi Thomas,

As the crash didn't happen when la_acars_decode_apps was called when I built v1.3.0 of libacars from source I didn't investigate it further.

I was looking in arincparse.cpp and void ArincParse::try_acars_apps(ACARSItem &acarsitem, la_msg_dir msg_dir) of JAERO and put qDebug() lines before and after la_acars_decode_apps was called.

I had compiled everything but libacars myself and then copied your v1.3.0 release of zlib1.dll and libacars.dll to the application directory of JAERO.

I was playing through some audio and noticed the following message result would cause JAERO to crash if la_acars_decode_apps was allowed to do its thing (the qDebug() before la_acars_decode_apps was printed then the crash happened and the following message wouldn't be shown)...

 AES:06A04B GES:C1 2 .A7-ACL ! AA D Airbus A330-202 Qatar Airways

	/PIKCPYA.AT1.A7-ACL2222121DD154664587343282C02F9C

	FANS-1/A CPDLC Message:
	 CPDLC Uplink Message:
	  Header:
	   Msg ID: 4
	   Timestamp: 08:33:08
	  Message data:
	   AT [time] CONTACT [icaounitname] [frequency]
	    Time: 08:42
	    Facility Name: LECM
	    Facility function: center
	    VHF: 135.955 MHz

Here is a link to an audio clip with this message in it, JAERO compiled by me, and libacars.dll compiled by you. On my Windows system that crashes every time the audio sample is played...

https://drive.google.com/open?id=1cwLwa4cupGrr2sUYVjOttw8_Hebr3XoU

Here is the following with the same build of JAERO but this time using the libacars.dll I compiled myself. Playing the same audio clip as above it doesn't crash on my system...

https://drive.google.com/open?id=1kqzn263AYjXQRb5t-zk-pdcG_IgVhQsB

When it does crash playing the sample no useful debug information is given; just that JAERO returned with some negative exit code. I did try compiling JAERO in debug mode but still no useful information was given.

I could be wrong but to me it seems like some sort of incompatibility between our two build environments or what we doing with them. I have noticed your build of libacars.dll is around 500KB while mine is around 1MB.

Cheers,
Jonti

from libacars.

Just tested both versions on Windows 10 and both run fine - no crashes, CPDLC message decodes properly. There must be some other factor which we are missing here.

from libacars.

Hi Thomas,

That is interesting. I am now thinking it might be the CPU instruction set issue. The CPU I'm using supports the following extensions...

MMX,SSE,SSE2,SSE3,SSSE3,SSE4.1,SSE4.2,EM64T and VT-x.

Others such as AVX are unsupported.

I ran the one that crashes for me using gdb and it crashes with the following output...

Thread 1 received signal SIGILL, Illegal instruction.
0x0000000066309aef in libacars!la_vstring_append_buffer ()

Looking into the disassembly I see that this instruction is...

=> 0x0000000066309aef <+8207>:  vmovdqa 0x60(%rsp),%xmm0

vmovdqa is an AVX extension (see https://docs.oracle.com/cd/E36784_01/html/E36859/gntbd.html ).

So that seems to be the problem. To solve it I suggest you disable AVX/AVX2/FMA instruction sets. I see there are some posts on the Internet about people trying to disable these instruction sets. It looks like you have to add -mno-avx to gcc when compiling.

Cheers,
Jonti

from libacars.

Great catch @jontio, thanks! However it's also quite puzzling, because:

• I build binary releases with default -march (which is x86-64) and default -mtune (which is generic) and this causes all AVX flavors to be disabled.

• la_vstring_append_buffer() is never called - neither by JAERO directly nor internally from libacars.

• I can't see that vmovdqa instruction in gcc -S <all_other_flags> vstring.c assembly output.

However I see this:

movdqa  .LC1(%rip), %xmm0

This is an SSE2 instruction and it requires dest. memory address to be aligned on a 16-byte boundary or a general-protection exception may be generated. I suspect this is what's happening here. Anyway, this instruction can be eliminated from the code simply by changing -O3 to -O2 (yeah, -O3 is the cmake's default for release builds). So here it is:

https://drive.google.com/open?id=14br-aAU1cYDEL1SbeKT6wVXcnzle1Iq6

Can you guys check this build please?

from libacars.

Hi Tomasz,

I had a quick look to see what functions called what and la_vstring_append_buffer can be called when asn_sprintf is called. asn_sprintf is declared by you as...

int asn_sprintf(la_vstring *vstr,	/* Destination vstring pointer */
	asn_TYPE_descriptor_t *td,	/* ASN.1 type descriptor */
	const void *struct_ptr,		/* Structure to be printed */
	int indent);			/* Indentation level */

asn_sprintf-->_print2vstring-->la_vstring_append_buffer
asn_sprintf-->la_vstring_append_buffer

I have decompiled both your built DLLs (the one from your releases and the one with -o2 optimizations) which you can download from here...

https://drive.google.com/open?id=1xg5xPZj4qiuRxQHcDai1INpO7vZDshNq

As you can see there are vmovdqa opcodes in both DLLs.

I tried the the -o2 optimization build you did. It too crashes. This time it crashes in __pformat_float at 662f29af on an AVX instruction...

.text:662f2980 <__pformat_float>:
                           .text:662f2980 56                               push   %rsi
                           .text:662f2981 53                               push   %rbx
                           .text:662f2982 48 83 ec 78                      sub    $0x78,%rsp
                           .text:662f2986 44 8b 42 10                      mov    0x10(%rdx),%r8d
                           .text:662f298a db 29                            fldt   (%rcx)
                           .text:662f298c 48 89 d3                         mov    %rdx,%rbx
                           .text:662f298f 45 85 c0                         test   %r8d,%r8d
                           .text:662f2992 79 0d                            jns    0x662f29a1
                           .text:662f2994 c7 42 10 06 00 00 00             movl   $0x6,0x10(%rdx)
                           .text:662f299b 41 b8 06 00 00 00                mov    $0x6,%r8d
                           .text:662f29a1 db 7c 24 60                      fstpt  0x60(%rsp)
                           .text:662f29a5 48 8d 44 24 58                   lea    0x58(%rsp),%rax
                           .text:662f29aa 48 89 44 24 20                   mov    %rax,0x20(%rsp)
=====>                     .text:662f29af c5 f9 6f 44 24 60                vmovdqa 0x60(%rsp),%xmm0
                           .text:662f29b5 48 8d 54 24 30                   lea    0x30(%rsp),%rdx
                           .text:662f29ba 4c 8d 4c 24 5c                   lea    0x5c(%rsp),%r9
                           .text:662f29bf b9 03 00 00 00                   mov    $0x3,%ecx
                           .text:662f29c4 c5 f8 29 44 24 30                vmovaps %xmm0,0x30(%rsp)
                           .text:662f29ca e8 91 f6 ff ff                   callq  0x662f2060 <.text>
                           .text:662f29cf 44 8b 44 24 5c                   mov    0x5c(%rsp),%r8d
                           .text:662f29d4 48 89 c6                         mov    %rax,%rsi
                           .text:662f29d7 41 81 f8 00 80 ff ff             cmp    $0xffff8000,%r8d
                           .text:662f29de 74 40                            je     0x662f2a20
                           .text:662f29e0 8b 4c 24 58                      mov    0x58(%rsp),%ecx
                           .text:662f29e4 49 89 d9                         mov    %rbx,%r9
                           .text:662f29e7 48 89 c2                         mov    %rax,%rdx
                           .text:662f29ea e8 d1 fb ff ff                   callq  0x662f25c0 <__pformat_emit_float>
                           .text:662f29ef eb 0d                            jmp    0x662f29fe
                           .text:662f29f1 48 89 da                         mov    %rbx,%rdx
                           .text:662f29f4 b9 20 00 00 00                   mov    $0x20,%ecx
                           .text:662f29f9 e8 82 f7 ff ff                   callq  0x662f2180 <__pformat_putc>
                           .text:662f29fe 8b 43 0c                         mov    0xc(%rbx),%eax
                           .text:662f2a01 8d 50 ff                         lea    -0x1(%rax),%edx
                           .text:662f2a04 89 53 0c                         mov    %edx,0xc(%rbx)
                           .text:662f2a07 85 c0                            test   %eax,%eax
                           .text:662f2a09 7f e6                            jg     0x662f29f1
                           .text:662f2a0b 48 89 f1                         mov    %rsi,%rcx
                           .text:662f2a0e e8 4d 19 00 00                   callq  0x662f4360 <__freedtoa>
                           .text:662f2a13 90                               nop
                           .text:662f2a14 48 83 c4 78                      add    $0x78,%rsp
                           .text:662f2a18 5b                               pop    %rbx
                           .text:662f2a19 5e                               pop    %rsi
                           .text:662f2a1a c3                               retq   
                           .text:662f2a1b 0f 1f 44 00 00                   nopl   0x0(%rax,%rax,1)
                           .text:662f2a20 8b 4c 24 58                      mov    0x58(%rsp),%ecx
                           .text:662f2a24 49 89 d8                         mov    %rbx,%r8
                           .text:662f2a27 48 89 c2                         mov    %rax,%rdx
                           .text:662f2a2a e8 f1 f9 ff ff                   callq  0x662f2420 <__pformat_emit_inf_or_nan>
                           .text:662f2a2f 48 89 f1                         mov    %rsi,%rcx
                           .text:662f2a32 e8 29 19 00 00                   callq  0x662f4360 <__freedtoa>
                           .text:662f2a37 90                               nop
                           .text:662f2a38 48 83 c4 78                      add    $0x78,%rsp
                           .text:662f2a3c 5b                               pop    %rbx
                           .text:662f2a3d 5e                               pop    %rsi
                           .text:662f2a3e c3                               retq   
                           .text:662f2a3f 90                               nop

This I assume is a function in mingw_pformat.c and used by things like printf when needed when you say something like printf("%f",a_rand_float).

On Linux I believe that printf is implemented in the library libc ( http://www.delorie.com/djgpp/doc/libc/libc_624.html ). However for Windows I think it is in a library called libmsvcrt.

So it looks like AVX instructions aren't being disabled in the final DLL. Maybe the optimization commands like -o2 have no effect on things like mingw_pformat.c because these are in a library (maybe libmsvcrt?) that I assume are already compiled by someone else and just exist in some library that are blindly statically linked with?

I am struggling to figure out what's happening here so I tried compiling a very simple program...

#include <stdio.h>
#include <stdlib.h>
void main()
{
	float a_rand_float=rand();
	printf("test %f\n",a_rand_float);
}

gcc -c test.c

nm -gu test.o

U __main
U printf
U rand

nm --defined-only test.o

0000000000000000 b .bss
0000000000000000 d .data
0000000000000000 p .pdata
0000000000000000 r .rdata
0000000000000000 r .rdata$zzz
0000000000000000 t .text
0000000000000000 r .xdata
0000000000000000 T main

So you can see it's wanting printf and rand and only has main in it. For linking using 'ld' rather than 'gcc' these are the libraries I seemed to need...

ld test.o /e/msys64/mingw64/x86_64-w64-mingw32/lib/crt2.o -L/e/msys64/mingw64/x86_64-w64-mingw32/lib -L/e/msys64/mingw64/lib/gcc/x86_64-w64-mingw32/9.2.0 -lmingw32 -lgcc -lmsvcrt -lkernel32 -lmoldname -lmingwex -lmsvcrt

Breaking on printf with gdb I found myself in /c/Windows/system32/msvcrt.dll. So I had left my application and that was a bit of a dead end but does show that printf is implemented in /c/Windows/system32/msvcrt.dll.

I didn't find any __pformat_float in /c/Windows/system32/msvcrt.dll.

I don't think SSE2 instructions should be an issue.

Cheers,
Jonti

from libacars.

I had a quick look to see what functions called what and la_vstring_append_buffer can be called when asn_sprintf is called.

Ahh, yes, correct. grep without -r didn't catch it.

Maybe the optimization commands like -o2 have no effect on things like mingw_pformat.c because these are in a library (maybe libmsvcrt?) that I assume are already compiled by someone else and just exist in some library that are blindly statically linked with?

Right, all these __pformat_* functions are statically linked from libmingwex.a which is a part of mingw64-runtime which I had built with -march=native (because I'm running Gentoo, so why not ;-)). So I have just rebuilt this runtime with -march=x86-64 -mtune=generic and this one should finally work (at least I no longer see any vmovdqa in it):

https://drive.google.com/open?id=1qr_sGQomtfbYFNgMUqjdzLvvyLS50e79

from libacars.

Hi Tomasz,

Thanks for that. I tried that out and yes that works fine. So yup, that was the problem. That was an interesting puzzle.

Cheers,
Jonti

from libacars.

Great work Guys,
running now for 4hrs,no probs. Huge respect for your input to this,Brill work. Thank you for great S/W and your efforts
Cheers G7gqw

from libacars.

Released as 1.3.1.

https://github.com/szpajder/libacars/releases/tag/v1.3.1

Thanks to all involved.

from libacars.