1/25/2022 11:28 AM — InterLinked

I think the end of your sentence might have cut off/been cut off? When you say "causes the system to crash", do you mean Asterisk crashes and needs to be started again?
A backtrace is required for debugging crashes. Please run phreaknet enable-backtraces (and recompile/reinstall if necessary) and it should produce a core dump when it crashes. Then run "phreaknet backtrace" to process the core dump. That will produce the file needed.
Additionally, please post the output of "core show settings" if possible (if using "phreaknet trace", it should do this automatically).
Thanks!

1/25/2022 11:54 AM — paulash134

Sorry for the lack of correct terminology. Yes Asterisk crashes and needs to be restarted. I have run phreaknet enable-backtraces. i have run Phreaknet backtrace the Phreaknet trace is https://paste.interlinked.us/eqlod8c2l1.txt

PBX Core settings

Version: 18.9.0
Build Options: DONT_OPTIMIZE, COMPILE_DOUBLE, BETTER_BACKTRACES, BUILD_NATIVE, OPTIONAL_API
Maximum calls: Not set
Maximum open file handles: 1024
Root console verbosity: 3
Current console verbosity: 19
Debug level: 0
Trace level: 0
Maximum load average: 0.000000
Minimum free memory: 0 MB
Startup time: 16:53:30
Last reload time: 16:53:30
System: Linux/4.19.0 built by root on x86_64 2022-01-25 16:33:31 UTC
System name:
Entity ID: 00:00:00:00:00:00
PBX UUID: 4c19bcfe-141a-4c86-b9a8-bcaa4b1b9484
Default language: en
Language prefix: Enabled
User name and group: /
Executable includes: Disabled
Transcode via SLIN: Enabled
Transmit silence during rec: Disabled
Generic PLC: Enabled
Generic PLC on equal codecs: Disabled
Hide Msg Chan AMI events: Disabled
Min DTMF duration:: 80
Cache media frames: Enabled
RTP use dynamic payloads: 1
RTP dynamic payload types: 35-63,96-127

• Subsystems

  ---

  Manager (AMI): Disabled
  Web Manager (AMI/HTTP): Disabled
  Call data records: Enabled
  Realtime Architecture (ARA): Disabled

• Directories

  ---

  Configuration file: /etc/asterisk/asterisk.conf
  Configuration directory: /etc/asterisk
  Module directory: /usr/lib/asterisk/modules
  Spool directory: /var/spool/asterisk
  Log directory: /var/log/asterisk
  Run/Sockets directory: /var/run/asterisk
  PID file: /var/run/asterisk/asterisk.pid
  VarLib directory: /var/lib/asterisk
  Data directory: /var/lib/asterisk
  ASTDB: /var/lib/asterisk/astdb
  IAX2 Keys directory: /var/lib/asterisk/keys
  AGI Scripts directory: /var/lib/asterisk/agi-bin

1/25/2022 12:17 PM — InterLinked

No worries, Paul, thanks for providing the additional info.
This appears to be a novel issue I have not seen before. Which version of Debian are you running - 10 or 11?
I'm still running 10 - though with a newer 5.x kernel - but I haven't had this issue.

Does the issue happen when calling any number on that node? e.g. 511, 211, 231-1111, etc. or just that particular one?
Does it replicate consistently? e.g. every time you call that number, it consistently crashes?

Can you also provides the output of the CLI command "keys show"?
And in your regular terminal: ls -la /var/lib/asterisk/keys

I think an issue may need to be opened upstream with Asterisk, which I can do, but I want to be sure of all the details first and see if I can replicate this in any way.

1/25/2022 12:33 PM — paulash134

Debian 10 - I have tried many of the numbers in the directory. I don't have a log of them as I go off hook to dial them but the numbers I remember are 231 1111, 234 1111, 976 3333. Every time consistently crashes. I can, however, get through to my own Time 980 1212, DISA 980 1111 and Roberts Time 442 1212 and DISA 442 1111

Key Name Type Status Sum

phreaknetrsa PRIVATE [Loaded] bc876bb7a5f17693fd002044175e41db
phreaknetrsa PUBLIC [Loaded] 75de35465a6666451dccfa7dff13bf5d
phreaknet-rsa-voip.phreaknet.org PUBLIC [Loaded] ae5f7baaebdfff173719b1281035131c

root@linux:~# ls -la /var/lib/asterisk/keys
total 24
drwxr-xr-x 3 asterisk root 4096 Jan 25 16:14 .
drwxr-xr-x 14 asterisk root 4096 Jan 25 17:29 ..
-rw-r--r-- 1 root root 271 Jan 24 08:45 phreaknet-rsa-voip.phreaknet.org.pub
-rw------- 1 root root 887 Jan 21 19:50 phreaknetrsa.key
-rw-r--r-- 1 root root 272 Jan 21 19:50 phreaknetrsa.pub
drwxr-xr-x 2 asterisk root 4096 Jan 20 22:46 stir_shaken

1/25/2022 12:39 PM — InterLinked

Got it, makes sense.
Can you try another call to 231-1111 now? I have my iax2 debug on so I can see if anything is happening here that might provide a hint.
Additionally, please capture the trace with core debug level 5, e.g. phreaknet trace --debug=5 I believe should do the trick. (Or you can manually do core set debug 5 and copy and paste if you prefer.)
There may be clues there in a possible bug in how chan_iax2 is setting up the encryption for the call. If I had to guess, that's where the problem might be.
Rob's node (442) doesn't support RSA authentication, which is why I think it works.
Your node may also not be requiring it at present, though it seems it supports at least since I just made an RSA authentication call to you fine.

1/25/2022 12:53 PM — InterLinked

Unfortunately, I can't reproduce the issue on a test machine with Asterisk 18.9 (though it is on Debian 11), so I may need you to try a few different things here.
Can you post your [general] from iax.conf?
After you've tried a call with debug level 3 or greater, then, if possible, run "phreaknet valgrind" to see if there are any memory issues may also be insightful. This will start Asterisk under valgrind - you would replicate the crash quickly (as Asterisk runs very slowly under valgrind, which is quite resource intensive). The output from that might offer additional clues.

We know that your Asterisk is crashing due to it trying to encrypt an IAX control frame, but precisely why isn't evident here; I don't see any null pointers, which is a common issue.

Thread 1 (Thread 0x7fbb4c2c6700 (LWP 1786)):

0 0x00007fbb77b2d97b in AES_encrypt () at /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1

1 0x00007fbb5518185c in __ast_aes_encrypt (in=0x7fbb4c2c1160 "", out=0x7fbb5c008ec0 "", ctx=0x565422403d54) at res_crypto.c:478

2 0x00007fbb55aef4ee in memcpy_encrypt (dst=0x7fbb5c008ec0 "", src=0x7fbb4c2c11a0 "", len=208, ecx=0x565422403d54) at chan_iax2.c:6437

    curblock = '000' <repeats 15 times>, "n"  
    x = 16  

3 0x00007fbb55aefc12 in encrypt_frame (ecx=0x565422403d54, fh=0x7fbb5c008ebc, poo=0x565422404034 "", datalen=0x7fbb5c008bc0) at chan_iax2.c:6517

    efh = 0x7fbb5c008ebc  
    padding = 26  
    workspace = 0x7fbb4c2c11a0 ""  
    __FUNCTION__ = "encrypt_frame"  

This is a system call to AES_encrypt in <openssl/aes.h>, but it could be crashing due to invalid arguments, not a problem with AES_encrypt itself.

1/25/2022 2:41 PM — paulash134

root@linux:~# phreaknet trace --debug=5
No ethernet interface found for seeding global EID. You will have to set it manually.
No ethernet interface found for seeding global EID. You will have to set it manually.
Core debug was OFF and is now 5.
No ethernet interface found for seeding global EID. You will have to set it manually.
Console verbose was OFF and is now 10.
Starting trace (verbose 10, debug 5): 1643139581
Starting CLI trace...
A CLI trace is now being collected. Reproduce the issue, then press ENTER to conclude the trace:
CLI trace terminated...
No ethernet interface found for seeding global EID. You will have to set it manually.
Unable to connect to remote asterisk (does /var/run/asterisk/asterisk.ctl exist?)
Unable to connect to remote asterisk (does /var/run/asterisk/asterisk.ctl exist?)
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 146k 100 39 100 146k 96 361k --:--:-- --:--:-- --:--:-- 361k
Paste URL: https://paste.interlinked.us/b9rhcsicrq.txt

1/25/2022 2:42 PM — paulash134

[general]
;bindport=4569 ; if you are NOT using 4569 as your PUBLIC IAX2 facing port for THIS switch, you should change the bindport so Asterisk listens on the forwarded port or call tokens will not work consistently
relaxdtmf=yes ; If your server has issues with DTMF this option may help
bandwidth=high ; This doesn't mean you have high bandwidth, it means allow high-bandwidth codecs. If you mess with this, your calls will sound awful because you're forbidding the codecs that should be used.
disallow=all ; allow only G711 or better codecs
allow=ulaw ; PCM G.711 uLaw (North America)
allow=alaw ; PCM G.711 aLaw (Europe, non-NANPA)
jitterbuffer=no
tos=0x12
delayreject=yes ; for increased security against brute force attacks
autokill=yes ; prevent stalling on call setup for unavailable hosts
encryption=yes ; Encryption is disabled by default. This allows it to be used.
trunk=yes ; More efficient when multiple IAX2 calls are up between two nodes.
maxcallnumbers_nonvalidated = 10 ; If you need to support nodes that don't do call tokens, set a limit or your server can be attacked.
; If you're not on C*NET, you may want to remove this line and the one below, and set requirecalltoken=yes globally, for security.
;calltokenoptional=0.0.0.0/0.0.0.0
requirecalltoken=yes

; You can copy and paste the sections generated by the user creation tool,
; or you can manually set these values and then set up your user.
[paulash134]
type = user
username = paulash134
secret = d9ff4dcca8697078c584bd13ae924be5c9c1476273780b46
auth = rsa,md5

include iax-phreaknet-rsa-in.conf

forceencryption = yes
requirecalltoken = yes
context = from-phreaknet ; this must be listed first (primary/default)
context = from-phreaknet-operator
;context = from-stepnet ; uncomment if this is a StepNet tandem
; insert any additional contexts here, since the first one is the default (primary)

include iax-phreaknet-rsa-out.conf

1/25/2022 2:44 PM — paulash134

root@linux:~# phreaknet valgrind
No ethernet interface found for seeding global EID. You will have to set it manually.
/usr/local/sbin/phreaknet: 1697: /usr/local/sbin/phreaknet: valgrind: not found
/tmp/asteriskvalgrind.txt

1/25/2022 2:49 PM — InterLinked

For that last bit, run phreaknet update && phreaknet valgrind and it should work then.
The script didn't used to install valgrind for you but now it does.

1/25/2022 3:39 PM — paulash134

==24610== Valgrind: failed to move log file descriptor into safe range, using stderr
==24610== Memcheck, a memory error detector
==24610== Copyright (C) 2002-2017, and GNU GPL'd, by Julian Seward et al.
==24610== Using Valgrind-3.14.0 and LibVEX; rerun with -h for copyright info
==24610== Command: asterisk -vvvvcg 9
==24610==
Killed
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 131k 100 39 100 131k 125 423k --:--:-- --:--:-- --:--:-- 422k
Paste URL: https://paste.interlinked.us/4wumgyo2iv.txt
/tmp/asteriskvalgrind.txt

1/25/2022 5:24 PM — InterLinked

It looks like you loaded Asterisk successfully in valgrind, but you didn't make any calls after it loaded (at least, not from what I can see of the output). When it loads, can you make a call - the crash needs to happen while valgrind is running.
Keeping in mind that Asterisk takes almost a minute to start up under valgrind, as opposed to seconds like it usually would, so you'd want to wait until it's fully loaded before doing so.

1/25/2022 6:01 PM — paulash134

Asterisk is running: I run phreaknet valgrind
root@linux:~# phreaknet valgrind
Reading package lists... Done
Building dependency tree
Reading state information... Done
valgrind is already the newest version (1:3.14.0-3).
0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.
No ethernet interface found for seeding global EID. You will have to set it manually.
Unable to connect to remote asterisk (does /var/run/asterisk/asterisk.ctl exist?)
==9562== Valgrind: failed to move log file descriptor into safe range, using stderr
==9562== Memcheck, a memory error detector
==9562== Copyright (C) 2002-2017, and GNU GPL'd, by Julian Seward et al.
==9562== Using Valgrind-3.14.0 and LibVEX; rerun with -h for copyright info
==9562== Command: asterisk -vvvvcg 9
==9562==
Killed
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 131k 100 39 100 131k 131 441k --:--:-- --:--:-- --:--:-- 440k
Paste URL: https://paste.interlinked.us/l81wbu0ozk.txt
/tmp/asteriskvalgrind.txt
I try to make a call and I get no further the line stays open and silent I can't dial although I tried keying in 231 1111. I'm happy to keep trying. When and if you have time I can share my screen with you.

1/25/2022 6:12 PM — InterLinked

You might find it helpful to run this command in one terminal window, and then open asterisk -r in another window so you can see what's actually happening as it's ongoing.

It may take a long time for Asterisk to do things that usually happen instantaneously in this mode; for instance, just processing individual dialplan calls might take seconds as opposed to milliseconds (it is REALLY slow). That's why being able to see on the CLI might be helpful.

Let me know if that helps; if not, we can certainly set up a time to debug together. Any chance you might be able to make it to Thursday's Asterisk debug/troubleshooting/help meeting? It's about this time, this Thursday. I think Chaz posted the details to the list.

1/25/2022 6:25 PM — paulash134

I watched the loading of the switch in a separate window and waited until it had all finished then tried to dial out, just silence but I keyed in the 231 1111 number, watching the CLI which didn't change then received engaged tone. I sent a phreaknet valgrind into the other screen, got the CLI eventually in the second screen and watched the system load. Tried to send a number to the system but still no tone. The screen I sent the command in to killed the operation at about the same time on each occasion. I will look up the debug troubleshooting help meeting, I should be able to make it. Thank you for all your help.

1/25/2022 6:26 PM — paulash134

root@linux:~# phreaknet valgrind
Reading package lists... Done
Building dependency tree
Reading state information... Done
valgrind is already the newest version (1:3.14.0-3).
0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.
No ethernet interface found for seeding global EID. You will have to set it manually.
==18265== Valgrind: failed to move log file descriptor into safe range, using stderr
==18265== Memcheck, a memory error detector
==18265== Copyright (C) 2002-2017, and GNU GPL'd, by Julian Seward et al.
==18265== Using Valgrind-3.14.0 and LibVEX; rerun with -h for copyright info
==18265== Command: asterisk -vvvvcg 9
==18265==
Killed
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 121k 100 39 100 121k 141 440k --:--:-- --:--:-- --:--:-- 440k
Paste URL: https://paste.interlinked.us/nakiplzwrv.txt
/tmp/asteriskvalgrind.txt
root@linux:~# phreaknet valgrind
Reading package lists... Done
Building dependency tree
Reading state information... Done
valgrind is already the newest version (1:3.14.0-3).
0 upgraded, 0 newly installed, 0 to remove and 0 not upgraded.
No ethernet interface found for seeding global EID. You will have to set it manually.
Unable to connect to remote asterisk (does /var/run/asterisk/asterisk.ctl exist?)
==18930== Valgrind: failed to move log file descriptor into safe range, using stderr
==18930== Memcheck, a memory error detector
==18930== Copyright (C) 2002-2017, and GNU GPL'd, by Julian Seward et al.
==18930== Using Valgrind-3.14.0 and LibVEX; rerun with -h for copyright info
==18930== Command: asterisk -vvvvcg 9
==18930==
Killed
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 120k 100 39 100 120k 128 395k --:--:-- --:--:-- --:--:-- 395k
Paste URL: https://paste.interlinked.us/svhbqdl9ky.txt
/tmp/asteriskvalgrind.txt

1/25/2022 6:29 PM — InterLinked

Now that I recall you mentioning you had only 512 MB, in conjunction with this answer, it may be getting killed due to a lack of memory: https://stackoverflow.com/a/10940186/

If you run "top" while valgrind is running and memory usage has approached 100%, that is likely what is happening then.

1/25/2022 6:31 PM — paulash134

Paste https://paste.interlinked.us/kurxgia7zx

1/25/2022 6:32 PM — paulash134

So more memory in the server would rectify all of this?

1/25/2022 6:46 PM — InterLinked

No, the issue would remain, it just might make tools like valgrind work a little better.
Probably not worth it; there are other ways to try to figure this out. valgrind might not be the best option here.
A less resource intensive option is MALLOC_DEBUG; you can try phreaknet update && phreaknet malloc-debug - this will recompile Asterisk with that option, then you reproduce the issue as with phreaknet trace. This should work on your system.
We can also take a closer look on Thursday.

1/26/2022 8:47 AM — paulash134

root@linux:~# phreaknet trace --debug=5
No ethernet interface found for seeding global EID. You will have to set it manually.
No ethernet interface found for seeding global EID. You will have to set it manually.
Core debug was OFF and is now 5.
No ethernet interface found for seeding global EID. You will have to set it manually.
Console verbose was OFF and is now 10.
No ethernet interface found for seeding global EID. You will have to set it manually.
IAX2 Debugging Enabled
Starting trace (verbose 10, debug 5): 1643204692
Starting CLI trace...
A CLI trace is now being collected. Reproduce the issue, then press ENTER to conclude the trace:
CLI trace terminated...
No ethernet interface found for seeding global EID. You will have to set it manually.
Unable to connect to remote asterisk (does /var/run/asterisk/asterisk.ctl exist?)
Unable to connect to remote asterisk (does /var/run/asterisk/asterisk.ctl exist?)
% Total % Received % Xferd Average Speed Time Time Time Current
Dload Upload Total Spent Left Speed
100 147k 100 39 100 147k 130 494k --:--:-- --:--:-- --:--:-- 494k
Paste URL: https://paste.interlinked.us/yxjyrjcdu8.txt

1/27/2022 8:03 PM — paulash134

[Jan 28 01:00:28] CAPABILITY2 : Unknown
[Jan 28 01:00:28] ADSICPE : 0
[Jan 28 01:00:28] DATE TIME : 2022-01-28 01:00:28
[Jan 28 01:00:28] VARIABLE : nodevia=9801111
[Jan 28 01:00:28] VARIABLE : dialed=2311111
[Jan 28 01:00:28]
[Jan 28 01:00:28] DEBUG[6728]: devicestate.c:361 _ast_device_state: No provider found, checking channel drivers for IAX2 - 157.230.89.4:4569
[Jan 28 01:00:28] DEBUG[6728]: chan_iax2.c:14560 iax2_devicestate: Checking device state for device 157.230.89.4
[Jan 28 01:00:28] DEBUG[6728]: devicestate.c:466 do_state_change: Changing state for IAX2/157.230.89.4:4569 - state 4 (Invalid)
[Jan 28 01:00:28] DEBUG[6796]: app_queue.c:2604 device_state_cb: Device 'IAX2/157.230.89.4:4569' changed to state '4' (Invalid) but we don't care because they're not a member of any queue.
[Jan 28 01:00:28] -- Called IAX2/phreaknet:1ffa893b1657b12a79be1ecbded0c3d69dac80d314284d14:[phreaknetrsa]@voip.phreaknet.org/2311111
[Jan 28 01:00:28] DEBUG[9064][C-00000001]: app_dial.c:1231 wait_for_answer: Local/2311111@phreaknet-route-00000001;2
[Jan 28 01:00:28] DEBUG[9064][C-00000001]: channel.c:5744 set_format: Channel IAX2/157.230.89.4:4569-12117 setting read format path: ulaw -> ulaw
[Jan 28 01:00:28] DEBUG[9064][C-00000001]: channel.c:5744 set_format: Channel Local/2311111@phreaknet-route-00000001;2 setting write format path: ulaw -> ulaw
[Jan 28 01:00:28] DEBUG[9064][C-00000001]: channel.c:5744 set_format: Channel Local/2311111@phreaknet-route-00000001;2 setting read format path: ulaw -> ulaw
[Jan 28 01:00:28] DEBUG[9064][C-00000001]: channel.c:5744 set_format: Channel IAX2/157.230.89.4:4569-12117 setting write format path: ulaw -> ulaw
[Jan 28 01:00:28] Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: CTOKEN
[Jan 28 01:00:28] Timestamp: 00012ms SCall: 00001 DCall: 12117 157.230.89.4:4569
[Jan 28 01:00:28] CALLTOKEN : 51 bytes
[Jan 28 01:00:28]
[Jan 28 01:00:28] DEBUG[6766][C-00000001]: chan_iax2.c:10406 socket_process_helper: Received packet 0, (6, 40)
[Jan 28 01:00:28] DEBUG[6766][C-00000001]: chan_iax2.c:10503 socket_process_helper: Cancelling transmission of packet 0
[Jan 28 01:00:28] DEBUG[6766][C-00000001]: chan_iax2.c:10677 socket_process_helper: IAX subclass 40 received
[Jan 28 01:00:28] DEBUG[6766][C-00000001]: chan_iax2.c:10686 socket_process_helper: For call=12117, set last=12
[Jan 28 01:00:28] DEBUG[6763]: chan_iax2.c:3410 send_packet: Sending 84 on 12117/0 to 157.230.89.4:4569
[Jan 28 01:00:28] Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW
[Jan 28 01:00:28] Timestamp: 00084ms SCall: 12117 DCall: 00000 157.230.89.4:4569
[Jan 28 01:00:28] VERSION : 2
[Jan 28 01:00:28] CALLED NUMBER : 2311111
[Jan 28 01:00:28] CODEC_PREFS : (ulaw|alaw)
[Jan 28 01:00:28] CALLING NUMBER : 9802368
[Jan 28 01:00:28] CALLING PRESNTN : 0
[Jan 28 01:00:28] CALLING TYPEOFN : 0
[Jan 28 01:00:28] CALLING TRANSIT : 0
[Jan 28 01:00:28] CALLING ANI2 : 0
[Jan 28 01:00:28] CALLING NAME : John Smith
[Jan 28 01:00:28] LANGUAGE : en
[Jan 28 01:00:28] USERNAME : phreaknet
[Jan 28 01:00:28] ENCRYPTION : 32769
[Jan 28 01:00:28] FORMAT : 4
[Jan 28 01:00:28] FORMAT2 : ulaw
[Jan 28 01:00:28] CAPABILITY : 12
[Jan 28 01:00:28] CAPABILITY2 : Unknown
[Jan 28 01:00:28] ADSICPE : 0
[Jan 28 01:00:28] DATE TIME : 2022-01-28 01:00:28
[Jan 28 01:00:28] VARIABLE : nodevia=9801111
[Jan 28 01:00:28] VARIABLE : dialed=2311111
[Jan 28 01:00:28] CALLTOKEN : 51 bytes
[Jan 28 01:00:28]
[Jan 28 01:00:28] Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: ACK
[Jan 28 01:00:28] Timestamp: 00084ms SCall: 09752 DCall: 12117 157.230.89.4:4569
[Jan 28 01:00:28] DEBUG[6767][C-00000001]: chan_iax2.c:10406 socket_process_helper: Received packet 0, (6, 4)
[Jan 28 01:00:28] DEBUG[6767][C-00000001]: chan_iax2.c:10503 socket_process_helper: Cancelling transmission of packet 0
[Jan 28 01:00:28] DEBUG[6767][C-00000001]: chan_iax2.c:10677 socket_process_helper: IAX subclass 4 received