Not seeing HFDL messages or verification of listening

[cbodden]

I have been trying to debug why HFDL is not being seen by the acars_router and it doesn't seem to be listening.

Here is the docker output :

  from distutils.util import strtobool

2024-03-26 18:54:50 [INFO] [acars_router.core] serving ACARS on TCP port 15550
2024-03-26 18:54:50 [INFO] [acars_router.core] serving VDLM2 on TCP port 15555
2024-03-26 18:54:50 [INFO] [acars_router.core] serving ACARS via ZMQ over TCP, port: 45550
2024-03-26 18:54:50 [INFO] [acars_router.core] serving VDLM2 via ZMQ over TCP, port: 45555
2024-03-26 18:54:50 [INFO] [acars_router.core] sending ACARS via UDP to acarshub:5550
2024-03-26 18:54:50 [INFO] [acars_router.core] sending VDLM2 via UDP to acarshub:5555
2024-03-26 18:54:50 [INFO] [acars_router.core] Listening for ACARS UDP on port 5550
2024-03-26 18:54:50 [INFO] [acars_router.core] Listening for ACARS TCP on port 5550
2024-03-26 18:54:50 [INFO] [acars_router.core] Listening for VDLM2 UDP on port 5555
2024-03-26 18:54:50 [INFO] [acars_router.core] Listening for VDLM2 TCP on port 5555

And here is the compose file :

 container_name: acars_router
 hostname: acars_router
 image: ghcr.io/sdr-enthusiasts/acars_router:latest_nohealthcheck
 restart: ${RESTART}
 depends_on:
   - acarsdec
   - vdlm2dec
 environment:
   - AR_ENABLE_DEDUPE=true
   - AR_LISTEN_UDP_ACARS=5550
   - AR_LISTEN_TCP_ACARS=5550
   - AR_LISTEN_UDP_VDLM2=5555
   - AR_LISTEN_TCP_VDLM2=5555
   - AR_LISTEN_UDP_HFDL=5556
   - AR_LISTEN_TCP_HFDL=5556
   - AR_SEND_UDP_ACARS=acarshub:5550
   - AR_SEND_UDP_HFDL=acarshub:5556
   - AR_SEND_UDP_VDLM2=acarshub:5555
   - AR_STATS_EVERY=30
   - AR_STATS_VERBOSE=true
   - TZ=${FEEDER_TZ}
 tmpfs:
   - /run:exec,size=64M
   - /var/log

I know that the router is working since ACARS and VDLM messages get routed accordingly but in the HFDL container i see the logs saying there were messages but the router seems to ignore / block.

Any help would rock!!

[fredclausen]

Hi! My first thought is the problem actually isn't in acars_router, but in ACARS Hub itself. You should have, off of the top of my head, ENABLE_HFDL=external in your ACARS Hub config. If it's present, then ACARS Hub isn't likely the problem.

If the above doesn't fix it, you could set AR_VERBOSITY=debug and have a look at the logs? It'll get fairly noisy, but it should start giving us clues as to where the problem is.

[cbodden]

Hi! My first thought is the problem actually isn't in acars_router, but in ACARS Hub itself. You should have, off of the top of my head, ENABLE_HFDL=external in your ACARS Hub config. If it's present, then ACARS Hub isn't likely the problem.

If the above doesn't fix it, you could set AR_VERBOSITY=debug and have a look at the logs? It'll get fairly noisy, but it should start giving us clues as to where the problem is.

I have enabled ENABLE_HFDL=external in the hub already. I will do a debug verbosity to see what it says and report back.

Thank you!

[fredclausen]

Sounds good. I should have added it will likely be helpful to do something like docker logs -f acars_router | grep 'hfdl'.

[cbodden]

I restarted with the AR_VERBOSITY=debug flag on and it kept looping this error :

/opt/acars_router/acars_router.py:4: DeprecationWarning: The distutils package is deprecated and slated for removal in Python 3.12. Use setuptools or check PEP 632 for potential alternatives
  from distutils.util import strtobool
Traceback (most recent call last):
  File "/opt/acars_router/acars_router.py", line 1825, in <module>
    default=int(os.getenv("AR_VERBOSITY", 0)),
ValueError: invalid literal for int() with base 10: 'debug'

[fredclausen]

Oh....I just realized the problem. The no_healthcheck tag is a very, very very old version of acars router. Switch to latest. There is no health check included in latest any more.

If that doesn't solve it I'll be surprised :)

[cbodden]

Oh....I just realized the problem. The no_healthcheck tag is a very, very very old version of acars router. Switch to latest. There is no health check included in latest any more.

If that doesn't solve it I'll be surprised :)

I feel like an idiot but that immediately fixed it. I should have tested that first but didn't even think about it.

This is the non-debug output now so it referenced HFDL :

[INFO ][2024-03-26T21:35:32]Starting ACARS input servers
[INFO ][2024-03-26T21:35:32]Starting ACARS Output Servers
[INFO ][2024-03-26T21:35:32]Starting VDLM Output Servers
[INFO ][2024-03-26T21:35:32]Starting HFDL Output Servers
[INFO ][2024-03-26T21:35:32]Starting UDP listener servers for ACARS
[INFO ][2024-03-26T21:35:32]Starting UDP listener servers for HFDL
[INFO ][2024-03-26T21:35:32]Starting ACARS UDP Sender
[INFO ][2024-03-26T21:35:32]Starting HFDL UDP Sender
[INFO ][2024-03-26T21:35:32]Starting UDP listener servers for VDLM
[INFO ][2024-03-26T21:35:32]Starting VDLM UDP Sender
[INFO ][2024-03-26T21:35:32]Starting TCP listener servers for ACARS
[INFO ][2024-03-26T21:35:32]Starting HFDL TCP Server 0.0.0.0:15556 
[INFO ][2024-03-26T21:35:32]Starting ZMQ listener servers for ACARS
[INFO ][2024-03-26T21:35:32]Starting TCP listener servers for VDLM
[INFO ][2024-03-26T21:35:32]Starting VDLM TCP Server 0.0.0.0:15555 
[INFO ][2024-03-26T21:35:32][UDP SERVER: ACARS_UDP_LISTEN_0.0.0.0:5550]: Listening on: 0.0.0.0:5550
[INFO ][2024-03-26T21:35:32]Starting TCP listener servers for HFDL
[INFO ][s6-rc: info: service legacy-services successfully started
2024-03-26T21:35:32]Starting ZMQ listener servers for HFDL
[INFO ][2024-03-26T21:35:32]Starting ACARS TCP Server 0.0.0.0:15550 
[INFO ][2024-03-26T21:35:32][TCP Listener SERVER: ACARS_TCP_LISTEN_5550]: Listening on: 0.0.0.0:5550
[INFO ][2024-03-26T21:35:32][UDP SERVER: HFDL_UDP_LISTEN_0.0.0.0:5556]: Listening on: 0.0.0.0:5556
[INFO ][2024-03-26T21:35:32][UDP SERVER: VDLM_UDP_LISTEN_0.0.0.0:5555]: Listening on: 0.0.0.0:5555
[INFO ][2024-03-26T21:35:32]Starting ZMQ_SENDER_SERVER_HFDL_45556
[INFO ][2024-03-26T21:35:32][TCP Listener SERVER: HFDL_TCP_LISTEN_5556]: Listening on: 0.0.0.0:5556
[INFO ][2024-03-26T21:35:32]Starting ZMQ listener servers for VDLM
[INFO ][2024-03-26T21:35:32]Starting ZMQ_SENDER_SERVER_ACARS_45550
[INFO ][2024-03-26T21:35:32][TCP Listener SERVER: VDLM_TCP_LISTEN_5555]: Listening on: 0.0.0.0:5555
[INFO ][2024-03-26T21:35:32]Starting ZMQ_SENDER_SERVER_VDLM_45555

Thank you for being so responsive and helpful. Next time i will pay better attention!!!

[fredclausen]

I’m glad that was the problem. Next time I rebuild the container I’ll make sure we include a no_healthcheck tag to avoid this cropping up in the future.