search

charlie-foxtrot / RTLSDR-Airband

Multichannel AM/NFM demodulator
GNU General Public License v3.0
761 stars 135 forks source link

icecast output dropped on max backlog #133

Closed danmilon closed 4 years ago

danmilon commented 5 years ago

When configured to output to an icecast server, if it becomes unreachable for a period of time and the backlog fills up, the output is be dropped, but rtlsdr-airband keeps running. I suppose this applies to all kinds of outputs.

For example:

Writing to /archives/xxx.mp3
<network drops>
Lost connection to audio-in.liveatc.net:8010/xxx_gnd
Trying to reconnect to audio-in.liveatc.net:8010/xxx_gnd...
Connecting to audio-in.liveatc.net:8010/xxx_gnd...
Exceeded max backlog for audio-in.liveatc.net:8010/xxx_app, disconnecting
Lost connection to audio-in.liveatc.net:8010/xxx_app
Exceeded max backlog for audio-in.liveatc.net:8010/xxx_twr, disconnecting
Lost connection to audio-in.liveatc.net:8010/xxx_twr
<network is restored, but icecast outputs are shutdown>
Writing to /archives/xxx.mp3

I understand that it cannot keep buffering indefinitely and eventually exhaust resources. But keeping running with a half baked configuration is not preferred either.

Instead, I see two possible alternative behaviours:

  1. When the backlog fills up, clear it and as long as the output is down don't keep adding to it. In the meantime, keep retrying to reset the output, indefinitely. When it is in operational state, start adding again to the buffer.
  2. Gracefully exit, in order to be rerun by the service monitor (e.g. systemd).

What do you think?

szpajder commented 5 years ago

No problem here. When the connection fails, it keeps trying to reconnect every 10 seconds, indefinitely, until it succeeds. This is how it works since the dawn of time.

Jul 22 07:44:01 rasp03 rtl_airband[432]: Could not connect to audio-in.liveatc.net:8010/yyy Jul 22 07:44:11 rasp03 rtl_airband[432]: Trying to reconnect to audio-in.liveatc.net:8010/xxx... Jul 22 07:44:11 rasp03 rtl_airband[432]: Connecting to audio-in.liveatc.net:8010/xxx... Jul 22 07:44:12 rasp03 rtl_airband[432]: Could not connect to audio-in.liveatc.net:8010/xxx Jul 22 07:44:12 rasp03 rtl_airband[432]: Trying to reconnect to audio-in.liveatc.net:8010/yyy... Jul 22 07:44:12 rasp03 rtl_airband[432]: Connecting to audio-in.liveatc.net:8010/yyy... Jul 22 07:44:12 rasp03 rtl_airband[432]: Could not connect to audio-in.liveatc.net:8010/yyy Jul 22 07:44:22 rasp03 rtl_airband[432]: Trying to reconnect to audio-in.liveatc.net:8010/xxx... Jul 22 07:44:22 rasp03 rtl_airband[432]: Connecting to audio-in.liveatc.net:8010/xxx... Jul 22 07:44:22 rasp03 rtl_airband[432]: Could not connect to audio-in.liveatc.net:8010/xxx Jul 22 07:44:22 rasp03 rtl_airband[432]: Trying to reconnect to audio-in.liveatc.net:8010/yyy... Jul 22 07:44:22 rasp03 rtl_airband[432]: Connecting to audio-in.liveatc.net:8010/yyy... Jul 22 07:44:22 rasp03 rtl_airband[432]: Could not connect to audio-in.liveatc.net:8010/yyy

danmilon commented 5 years ago

Hey, thanks for the prompt reply.

Weird, that didn't happen in my case. Here are the logs with timestamps. After it was restarted, it connected just fine, which led me to assume that it didn't keep retrying. Am I missing something?

Jul 30 11:02:43 rtlsdr-atc-1 cb3dc747e561[345]: Writing to /archives/emerg/emerg_20190730_11.mp3
Jul 30 11:04:47 rtlsdr-atc-1 cb3dc747e561[345]: Lost connection to audio-in.liveatc.net:8010/xxx_gnd
Jul 30 11:04:51 rtlsdr-atc-1 cb3dc747e561[345]: Trying to reconnect to audio-in.liveatc.net:8010/xxx_gnd...
Jul 30 11:04:51 rtlsdr-atc-1 cb3dc747e561[345]: Connecting to audio-in.liveatc.net:8010/xxx_gnd...
Jul 30 11:04:56 rtlsdr-atc-1 cb3dc747e561[345]: Exceeded max backlog for audio-in.liveatc.net:8010/xxx_app, disconnecting
Jul 30 11:04:56 rtlsdr-atc-1 cb3dc747e561[345]: Lost connection to audio-in.liveatc.net:8010/xxx_app
Jul 30 11:05:20 rtlsdr-atc-1 cb3dc747e561[345]: Exceeded max backlog for audio-in.liveatc.net:8010/xxx_twr, disconnecting
Jul 30 11:05:20 rtlsdr-atc-1 cb3dc747e561[345]: Lost connection to audio-in.liveatc.net:8010/xxx_twr
Jul 30 12:00:00 rtlsdr-atc-1 cb3dc747e561[345]: Writing to /archives/app/app_20190730_12.mp3
Jul 30 12:00:15 rtlsdr-atc-1 cb3dc747e561[345]: Writing to /archives/twr/twr_20190730_12.mp3
Jul 30 12:01:52 rtlsdr-atc-1 cb3dc747e561[345]: Writing to /archives/gnd/gnd_20190730_12.mp3
Jul 30 12:35:11 rtlsdr-atc-1 cb3dc747e561[345]: Writing to /archives/emerg/emerg_20190730_12.mp3
Jul 30 13:00:08 rtlsdr-atc-1 cb3dc747e561[345]: Writing to /archives/app/app_20190730_13.mp3
Jul 30 13:00:18 rtlsdr-atc-1 cb3dc747e561[345]: Writing to /archives/twr/twr_20190730_13.mp3
Jul 30 13:01:33 rtlsdr-atc-1 cb3dc747e561[345]: Writing to /archives/emerg/emerg_20190730_13.mp3
Jul 30 13:08:36 rtlsdr-atc-1 cb3dc747e561[345]: Writing to /archives/gnd/gnd_20190730_13.mp3
Jul 30 14:00:34 rtlsdr-atc-1 cb3dc747e561[345]: Writing to /archives/twr/twr_20190730_14.mp3
Jul 30 14:00:54 rtlsdr-atc-1 cb3dc747e561[345]: Writing to /archives/app/app_20190730_14.mp3
Jul 30 14:01:09 rtlsdr-atc-1 cb3dc747e561[345]: Writing to /archives/gnd/gnd_20190730_14.mp3
Jul 30 14:06:12 rtlsdr-atc-1 cb3dc747e561[345]: Writing to /archives/emerg/emerg_20190730_14.mp3
<I SIGTERM IT>
Jul 30 14:59:56 rtlsdr-atc-1 cb3dc747e561[345]: Got signal 15, exiting
Jul 30 14:59:56 rtlsdr-atc-1 cb3dc747e561[345]: Freeing GPU memory
Jul 30 14:59:56 rtlsdr-atc-1 cb3dc747e561[345]: Cleaning up
Jul 30 14:59:56 rtlsdr-atc-1 cb3dc747e561[345]: Input threads closed
Jul 30 15:00:00 rtlsdr-atc-1 cb3dc747e561[345]: RTLSDR-Airband version 3.0.1 starting
Jul 30 15:00:04 rtlsdr-atc-1 cb3dc747e561[345]: Connecting to audio-in.liveatc.net:8010/xxx_twr...
Jul 30 15:00:04 rtlsdr-atc-1 cb3dc747e561[345]: Connected to audio-in.liveatc.net:8010/xxx_twr
Jul 30 15:00:06 rtlsdr-atc-1 cb3dc747e561[345]: Connecting to audio-in.liveatc.net:8010/xxx_gnd...
Jul 30 15:00:06 rtlsdr-atc-1 cb3dc747e561[345]: Connected to audio-in.liveatc.net:8010/xxx_gnd
Jul 30 15:00:06 rtlsdr-atc-1 cb3dc747e561[345]: Found Rafael Micro R820T tuner
Jul 30 15:00:06 rtlsdr-atc-1 cb3dc747e561[345]: [R82XX] PLL not locked!
Jul 30 15:00:06 rtlsdr-atc-1 cb3dc747e561[345]: Device #2: gain set to 14.40 dB
Jul 30 15:00:06 rtlsdr-atc-1 cb3dc747e561[345]: RTLSDR device 2 initialized
Jul 30 15:00:07 rtlsdr-atc-1 cb3dc747e561[345]: Connecting to audio-in.liveatc.net:8010/xxx_app...
Jul 30 15:00:08 rtlsdr-atc-1 cb3dc747e561[345]: Connected to audio-in.liveatc.net:8010/xxx_app
szpajder commented 5 years ago

It works very reliably, so I guess you must have hit some kind of corner case. Does it happen very often?

Can you post your config (without passwords, etc)?

danmilon commented 5 years ago 
devices:
({
  type = "rtlsdr";
  serial = "00000001";
  gain = 14;
  centerfreq = xxx;
  sample_rate = 2.56;
  channels:
  (
    {
      freq = xxx;
      outputs: (
        {
          type = "icecast";
          server = "audio-in.liveatc.net";
          port = 8010;
          mountpoint = "xxx_twr";
          name = "XXX Tower";
          genre = "ATC";
          username = "source";
          password = "";
        },
        {
          type = "file";
          directory = "/archives/twr";
          filename_template = "twr";
        }
      );
    },
    {
      freq = xxx;
      outputs: (
        {
          type = "file";
          directory = "/archives/emerg";
          filename_template = "emerg";
        }
      );
    },
    {
      freq = xxx;
      outputs: (
        {
          type = "icecast";
          server = "audio-in.liveatc.net";
          port = 8010;
          mountpoint = "xxx_gnd";
          name = "XXX Ground";
          genre = "ATC";
          username = "source";
          password = "";
        },
        {
          type = "file";
          directory = "/archives/gnd";
          filename_template = "gnd";
        }
      );
    },
    {
      freq = xxx;
      outputs: (
        {
          type = "file";
          directory = "/archives/unicom";
          filename_template = "unicom";
        }
      );
    }
  );
 },
 {
  type = "rtlsdr";
  serial = "00000002";
  gain = 16;
  centerfreq = xxx;
  sample_rate = 2.4;
  channels:
  (
    {
      freq = xxx;
      outputs: (
        {
          type = "icecast";
          server = "audio-in.liveatc.net";
          port = 8010;
          mountpoint = "xxx_app";
          name = "XXX Approach";
          genre = "ATC";
          username = "source";
          password = "";
        },
        {
          type = "file";
          directory = "/archives/app";
          filename_template = "app";
        }
      );
    }
  );
 },
 {
  type = "rtlsdr";
  serial = "00000003";
  gain = 14;
  sample_rate = 2.4;
  disable = true;
  channels:
  (
    {
      freq = xxx;
      outputs: (
        {
          type = "file";
          directory = "/archives/director";
          filename_template = "director";
        }
      );
    }
  )
 }
);
szpajder commented 5 years ago

I have tested your config (adapted slightly to my local environment) and it works correctly, ie. when the network connection is back, all feeds reconnect. It might some time though, because shout library does not impose any timeout on the connection setup operation, hence it will wait until the operating system decides to give up and returns a socket error. So looking at the log output that you posted:

Writing to /archives/xxx.mp3
<network drops>
Lost connection to audio-in.liveatc.net:8010/xxx_gnd
Trying to reconnect to audio-in.liveatc.net:8010/xxx_gnd...
Connecting to audio-in.liveatc.net:8010/xxx_gnd...

The last line says "Connecting" which means the reconnect operation for xxx_gnd is in progress. The program examines the status of each icecast output sequentially - if a particular output is disconnected, it will attempt to reconnect it (this is when "Connecting to..." message appears in the log) and it will wait before this operation completes or errors out before moving to the next output. So the question is how long did you wait after the network connection returned? Eventually the xxx_gnd reconnection attempt should succeed (and print "Connected to audio-in.liveatc.net:8010/xxx_gnd") or fail (and print "Could not connect to audio-in.liveatc.net:8010/xxx_gnd") and then subsequent outputs will be dealt with. This is what I observe in my tests of your config.

danmilon commented 5 years ago

Aha, I see. That partly clears up the picture. Do you know what the socket timeout is? I restarted it after an hour, and connected to it over the internet to do that, so connectivity was fine at the time of the restart.

By the way, I was now trying to get more logs from the time of the incident, and noticed another occurrence of a networking issue which it recovered from correctly, as you described.

Jul 31 10:02:20 rtlsdr-atc-1 cb3dc747e561[345]: Writing to /archives/emerg/emerg_20190731_10.mp3
Jul 31 10:04:47 rtlsdr-atc-1 cb3dc747e561[345]: Lost connection to audio-in.liveatc.net:8010/xxx_app
Jul 31 10:04:48 rtlsdr-atc-1 cb3dc747e561[345]: Lost connection to audio-in.liveatc.net:8010/xxx_twr
Jul 31 10:04:48 rtlsdr-atc-1 cb3dc747e561[345]: Lost connection to audio-in.liveatc.net:8010/xxx_gnd
Jul 31 10:04:50 rtlsdr-atc-1 cb3dc747e561[345]: Trying to reconnect to audio-in.liveatc.net:8010/xxx_twr...
Jul 31 10:04:50 rtlsdr-atc-1 cb3dc747e561[345]: Connecting to audio-in.liveatc.net:8010/xxx_twr...
Jul 31 10:04:52 rtlsdr-atc-1 cb3dc747e561[345]: Writing to /archives/gnd/gnd_20190731_10.mp3
Jul 31 10:06:02 rtlsdr-atc-1 cb3dc747e561[345]: Connected to audio-in.liveatc.net:8010/xxx_twr
Jul 31 10:06:02 rtlsdr-atc-1 cb3dc747e561[345]: Trying to reconnect to audio-in.liveatc.net:8010/xxx_gnd...
Jul 31 10:06:02 rtlsdr-atc-1 cb3dc747e561[345]: Connecting to audio-in.liveatc.net:8010/xxx_gnd...
Jul 31 10:06:04 rtlsdr-atc-1 cb3dc747e561[345]: Connected to audio-in.liveatc.net:8010/xxx_gnd
Jul 31 10:06:04 rtlsdr-atc-1 cb3dc747e561[345]: Trying to reconnect to audio-in.liveatc.net:8010/xxx_app...
Jul 31 10:06:04 rtlsdr-atc-1 cb3dc747e561[345]: Connecting to audio-in.liveatc.net:8010/xxx_app...
Jul 31 10:06:06 rtlsdr-atc-1 cb3dc747e561[345]: Connected to audio-in.liveatc.net:8010/xxx_app
Jul 31 11:00:00 rtlsdr-atc-1 cb3dc747e561[345]: Writing to /archives/twr/twr_20190731_11.mp3

I guess it really hit a corner case. I could try to reproduce it by dropping packets through iptables rules.

szpajder commented 5 years ago

Do you know what the socket timeout is?

This is driven by sysctl net.ipv4.tcp_syn_retries, which is set to 6 by default (meaning it will retransmit the initial SYN packet 6 times before it aborts). The backoff is exponential - the first retry goes after 1 second, the second one after next 2 sec, then 4 sec, etc, so it will eventually error out after 127 seconds.

I could try to reproduce it by dropping packets through iptables rules.

Good idea. It's also worth adding a few additional log() statemens to output.cpp (shout_setup() and output_check_thread() routines are of particular interest).

szpajder commented 5 years ago

Any success in reproducing this problem?

danmilon commented 5 years ago

sorry I was being lazy and I haven't tried yet.

danmilon commented 5 years ago

for reference, another manifestation of the issue.

Sep 04 08:00:09 art-atc-1 0f814ad3f481[355]: Writing to /archives/gnd_s/gnd_s_20190904_08.mp3
Sep 04 08:01:01 art-atc-1 0f814ad3f481[355]: Writing to /archives/del/del_20190904_08.mp3
Sep 04 08:41:07 art-atc-1 0f814ad3f481[355]: Lost connection to audio-in.liveatc.net:8010/xxx3_gnd_s
Sep 04 08:41:12 art-atc-1 0f814ad3f481[355]: Trying to reconnect to audio-in.liveatc.net:8010/xxx3_gnd_s...
Sep 04 08:41:17 art-atc-1 0f814ad3f481[355]: Connecting to audio-in.liveatc.net:8010/xxx3_gnd_s...
Sep 04 08:41:18 art-atc-1 0f814ad3f481[355]: Connected to audio-in.liveatc.net:8010/xxx3_gnd_s
Sep 04 08:47:25 art-atc-1 0f814ad3f481[355]: Lost connection to audio-in.liveatc.net:8010/xxx3_dir
Sep 04 08:47:25 art-atc-1 0f814ad3f481[355]: Lost connection to audio-in.liveatc.net:8010/xxx3_gnd_n
Sep 04 08:47:25 art-atc-1 0f814ad3f481[355]: Lost connection to audio-in.liveatc.net:8010/xxx3_del
Sep 04 08:47:25 art-atc-1 0f814ad3f481[355]: Lost connection to audio-in.liveatc.net:8010/xxx3_twr
Sep 04 08:47:26 art-atc-1 0f814ad3f481[355]: Lost connection to audio-in.liveatc.net:8010/xxx3_gnd_s
Sep 04 08:47:28 art-atc-1 0f814ad3f481[355]: Trying to reconnect to audio-in.liveatc.net:8010/xxx3_del...
Sep 04 08:47:28 art-atc-1 0f814ad3f481[355]: Connecting to audio-in.liveatc.net:8010/xxx3_del...
Sep 04 08:47:28 art-atc-1 0f814ad3f481[355]: Lost connection to audio-in.liveatc.net:8010/xxx3_twr1
Sep 04 08:47:30 art-atc-1 0f814ad3f481[355]: Connected to audio-in.liveatc.net:8010/xxx3_del
Sep 04 08:47:30 art-atc-1 0f814ad3f481[355]: Trying to reconnect to audio-in.liveatc.net:8010/xxx3_dir...
Sep 04 08:47:30 art-atc-1 0f814ad3f481[355]: Connecting to audio-in.liveatc.net:8010/xxx3_dir...
Sep 04 08:47:31 art-atc-1 0f814ad3f481[355]: Connected to audio-in.liveatc.net:8010/xxx3_dir
Sep 04 08:47:31 art-atc-1 0f814ad3f481[355]: Trying to reconnect to audio-in.liveatc.net:8010/xxx3_gnd_n...
Sep 04 08:47:31 art-atc-1 0f814ad3f481[355]: Connecting to audio-in.liveatc.net:8010/xxx3_gnd_n...
Sep 04 08:47:32 art-atc-1 0f814ad3f481[355]: Connected to audio-in.liveatc.net:8010/xxx3_gnd_n
Sep 04 08:47:32 art-atc-1 0f814ad3f481[355]: Trying to reconnect to audio-in.liveatc.net:8010/xxx3_gnd_s...
Sep 04 08:47:32 art-atc-1 0f814ad3f481[355]: Connecting to audio-in.liveatc.net:8010/xxx3_gnd_s...
Sep 04 08:47:34 art-atc-1 0f814ad3f481[355]: Connected to audio-in.liveatc.net:8010/xxx3_gnd_s
Sep 04 08:47:34 art-atc-1 0f814ad3f481[355]: Trying to reconnect to audio-in.liveatc.net:8010/xxx3_twr...
Sep 04 08:47:34 art-atc-1 0f814ad3f481[355]: Connecting to audio-in.liveatc.net:8010/xxx3_twr...
Sep 04 08:47:35 art-atc-1 0f814ad3f481[355]: Connected to audio-in.liveatc.net:8010/xxx3_twr
Sep 04 08:47:45 art-atc-1 0f814ad3f481[355]: Trying to reconnect to audio-in.liveatc.net:8010/xxx3_twr1...
Sep 04 08:47:50 art-atc-1 0f814ad3f481[355]: Could not connect to audio-in.liveatc.net:8010/xxx3_twr1
Sep 04 08:48:00 art-atc-1 0f814ad3f481[355]: Trying to reconnect to audio-in.liveatc.net:8010/xxx3_twr1...
Sep 04 08:48:00 art-atc-1 0f814ad3f481[355]: Connecting to audio-in.liveatc.net:8010/xxx3_twr1...
Sep 04 08:48:00 art-atc-1 0f814ad3f481[355]: Lost connection to audio-in.liveatc.net:8010/xxx3_twr
Sep 04 08:48:00 art-atc-1 0f814ad3f481[355]: Lost connection to audio-in.liveatc.net:8010/xxx3_del
Sep 04 08:48:01 art-atc-1 0f814ad3f481[355]: Lost connection to audio-in.liveatc.net:8010/xxx3_dir
Sep 04 08:48:01 art-atc-1 0f814ad3f481[355]: Connected to audio-in.liveatc.net:8010/xxx3_twr1
Sep 04 08:48:01 art-atc-1 0f814ad3f481[355]: Lost connection to audio-in.liveatc.net:8010/xxx3_gnd_n
Sep 04 08:48:02 art-atc-1 0f814ad3f481[355]: Trying to reconnect to audio-in.liveatc.net:8010/xxx3_del...
Sep 04 08:48:02 art-atc-1 0f814ad3f481[355]: Connecting to audio-in.liveatc.net:8010/xxx3_del...
Sep 04 08:48:03 art-atc-1 0f814ad3f481[355]: Connected to audio-in.liveatc.net:8010/xxx3_del
Sep 04 08:48:03 art-atc-1 0f814ad3f481[355]: Trying to reconnect to audio-in.liveatc.net:8010/xxx3_dir...
Sep 04 08:48:03 art-atc-1 0f814ad3f481[355]: Connecting to audio-in.liveatc.net:8010/xxx3_dir...
Sep 04 08:48:04 art-atc-1 0f814ad3f481[355]: Connected to audio-in.liveatc.net:8010/xxx3_dir
Sep 04 08:48:04 art-atc-1 0f814ad3f481[355]: Trying to reconnect to audio-in.liveatc.net:8010/xxx3_gnd_n...
Sep 04 08:48:04 art-atc-1 0f814ad3f481[355]: Connecting to audio-in.liveatc.net:8010/xxx3_gnd_n...
Sep 04 08:48:06 art-atc-1 0f814ad3f481[355]: Connected to audio-in.liveatc.net:8010/xxx3_gnd_n
Sep 04 08:48:06 art-atc-1 0f814ad3f481[355]: Trying to reconnect to audio-in.liveatc.net:8010/xxx3_twr...
Sep 04 08:48:06 art-atc-1 0f814ad3f481[355]: Connecting to audio-in.liveatc.net:8010/xxx3_twr...
Sep 04 08:48:07 art-atc-1 0f814ad3f481[355]: Connected to audio-in.liveatc.net:8010/xxx3_twr
Sep 04 08:49:32 art-atc-1 0f814ad3f481[355]: Exceeded max backlog for audio-in.liveatc.net:8010/xxx3_twr, disconnecting
Sep 04 08:49:32 art-atc-1 0f814ad3f481[355]: Lost connection to audio-in.liveatc.net:8010/xxx3_twr
Sep 04 08:49:37 art-atc-1 0f814ad3f481[355]: Trying to reconnect to audio-in.liveatc.net:8010/xxx3_twr...
Sep 04 08:49:42 art-atc-1 0f814ad3f481[355]: Could not connect to audio-in.liveatc.net:8010/xxx3_twr
Sep 04 08:49:43 art-atc-1 0f814ad3f481[355]: Lost connection to audio-in.liveatc.net:8010/xxx3_gnd_n
Sep 04 08:49:45 art-atc-1 0f814ad3f481[355]: Exceeded max backlog for audio-in.liveatc.net:8010/xxx3_twr1, disconnecting
Sep 04 08:49:45 art-atc-1 0f814ad3f481[355]: Lost connection to audio-in.liveatc.net:8010/xxx3_twr1
Sep 04 08:49:49 art-atc-1 0f814ad3f481[355]: Lost connection to audio-in.liveatc.net:8010/xxx3_del
Sep 04 08:49:51 art-atc-1 0f814ad3f481[355]: Lost connection to audio-in.liveatc.net:8010/xxx3_gnd_s
Sep 04 08:49:52 art-atc-1 0f814ad3f481[355]: Trying to reconnect to audio-in.liveatc.net:8010/xxx3_twr1...
Sep 04 08:49:53 art-atc-1 0f814ad3f481[355]: Lost connection to audio-in.liveatc.net:8010/xxx3_dir
Sep 04 08:49:55 art-atc-1 0f814ad3f481[355]: Connecting to audio-in.liveatc.net:8010/xxx3_twr1...
Sep 04 09:00:29 art-atc-1 0f814ad3f481[355]: Writing to /archives/xxx20190904_09.mp3
Sep 04 09:00:59 art-atc-1 0f814ad3f481[355]: Writing to /archives/xxx_20190904_09.mp3
danmilon commented 5 years ago

is it weird that it has only two socket fds? even though there are 5 or so different icecast outputs?

bash-4.4# ls -l /proc/1/fd
total 0
lr-x------    1 root     root            64 Sep  2 13:36 0 -> pipe:[12938]
l-wx------    1 root     root            64 Sep  2 13:36 1 -> pipe:[12939]
lrwx------    1 root     root            64 Sep  5 14:10 10 -> anon_inode:[timerfd]
lrwx------    1 root     root            64 Sep  5 14:10 11 -> /dev/bus/usb/001/004
lrwx------    1 root     root            64 Sep  5 14:10 12 -> /archives/xxx1.mp3
lrwx------    1 root     root            64 Sep  5 14:10 13 -> /archives/xxx2.mp3
lrwx------    1 root     root            64 Sep  5 14:10 14 -> /archives/xxx3.mp3
lr-x------    1 root     root            64 Sep  5 14:10 15 -> pipe:[20112]
l-wx------    1 root     root            64 Sep  5 14:10 16 -> pipe:[20112]
lrwx------    1 root     root            64 Sep  5 14:10 17 -> anon_inode:[timerfd]
lrwx------    1 root     root            64 Sep  5 14:10 18 -> /dev/bus/usb/001/007
lrwx------    1 root     root            64 Sep  5 14:10 19 -> /archives/xxx4.mp3
l-wx------    1 root     root            64 Sep  2 13:36 2 -> pipe:[12940]
lr-x------    1 root     root            64 Sep  5 14:10 20 -> pipe:[20745]
l-wx------    1 root     root            64 Sep  5 14:10 21 -> pipe:[20745]
lrwx------    1 root     root            64 Sep  5 14:10 22 -> anon_inode:[timerfd]
lrwx------    1 root     root            64 Sep  5 14:10 23 -> /dev/bus/usb/001/005
lr-x------    1 root     root            64 Sep  5 14:10 24 -> /dev/vcio
lrwx------    1 root     root            64 Sep  5 14:10 25 -> /archives/xxx5.mp3
lrwx------    1 root     root            64 Sep  2 13:36 3 -> socket:[34568576]
lrwx------    1 root     root            64 Sep  2 13:36 4 -> /archives/xxx6.mp3
lrwx------    1 root     root            64 Sep  2 13:36 5 -> socket:[17505]
lr-x------    1 root     root            64 Sep  2 13:36 6 -> pipe:[17506]
l-wx------    1 root     root            64 Sep  2 13:36 7 -> pipe:[17506]
lr-x------    1 root     root            64 Sep  5 14:10 8 -> pipe:[17507]
l-wx------    1 root     root            64 Sep  5 14:10 9 -> pipe:[17507]
danmilon commented 5 years ago

In strace there's a spam of

[pid    14] recvfrom(3, 0x7568981c, 1024, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
[pid    14] nanosleep({tv_sec=0, tv_nsec=10000000}, 0x75689c40) = 0
[pid    14] recvfrom(3, 0x7568981c, 1024, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
[pid    14] nanosleep({tv_sec=0, tv_nsec=10000000}, 0x75689c40) = 0
[pid    14] recvfrom(3, 0x7568981c, 1024, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
[pid    14] nanosleep({tv_sec=0, tv_nsec=10000000},  <unfinished ...>
[pid     1] nanosleep({tv_sec=0, tv_nsec=10000000},  <unfinished ...>
[pid    14] <... nanosleep resumed> 0x75689c40) = 0
[pid    14] recvfrom(3, 0x7568981c, 1024, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
[pid    14] nanosleep({tv_sec=0, tv_nsec=10000000},  <unfinished ...>
       EAGAIN or EWOULDBLOCK
              The socket is marked nonblocking and the receive operation would block, or a receive timeout had been set and  the  timeout  expired  before
              data  was  received.
szpajder commented 5 years ago

It seems that it attempted to reconnect to audio-in.liveatc.net:8010/xxx3_twr1 and hung there for over 10 minutes, preventing other outputs from reconnecting. This means it didn't hang at the TCP connection setup phase, because if it this was the case, it would timeout after 127 seconds and then retry. So my guess is that the TCP connection has been established and the HTTP request has been sent, but then the link dropped again, while the program was waiting for a HTTP response. As libshout library does not impose any time limit for receiving a response, it will essentially stay forever in this state and because the output status checking/reconnecting thread performs its work iterating sequentially over all configured Icecast outputs, it won't ever proceed to the next output. That's nasty, but quite simple to fix - instead of relying on system calls' timeouts we should just have our own timeout for Icecast connection setup. Please try the latest unstable branch - https://github.com/szpajder/RTLSDR-Airband/commit/e8a4aea8df772a45a9a21ccdcc54520609f02e79 imposes a timeout of 30 seconds for this purpose. A side effect is that the TCP connection setup timeout has also been shortened from 127 to 30 seconds.

danmilon commented 5 years ago

Looks like it works fine now.

Sep 09 08:24:39 art-atc-1 6c2bdf4f4886[369]: RTLSDR device 2 initialized
Sep 09 08:24:40 art-atc-1 6c2bdf4f4886[369]: Appending from pos 1314819 to /archives/gnd_s/gnd_s_20190909_08.mp3
Sep 09 08:24:42 art-atc-1 6c2bdf4f4886[369]: Appending from pos 1223446 to /archives/gnd_n/gnd_n_20190909_08.mp3
Sep 09 08:24:47 art-atc-1 6c2bdf4f4886[369]: Appending from pos 1055378 to /archives/twr1/twr1_20190909_08.mp3
Sep 09 08:25:09 art-atc-1 6c2bdf4f4886[369]: Appending from pos 547036 to /archives/del/del_20190909_08.mp3
Sep 09 08:25:25 art-atc-1 6c2bdf4f4886[369]: Appending from pos 746078 to /archives/twr2/twr2_20190909_08.mp3
Sep 09 08:34:38 art-atc-1 6c2bdf4f4886[369]: Lost connection to audio-in.liveatc.net:8010/xxx3_dir
Sep 09 08:34:40 art-atc-1 6c2bdf4f4886[369]: Trying to reconnect to audio-in.liveatc.net:8010/xxx3_dir...
Sep 09 08:34:42 art-atc-1 6c2bdf4f4886[369]: Connecting to audio-in.liveatc.net:8010/xxx3_dir...
Sep 09 08:34:52 art-atc-1 6c2bdf4f4886[369]: Connected to audio-in.liveatc.net:8010/xxx3_dir
Sep 09 08:35:30 art-atc-1 6c2bdf4f4886[369]: Lost connection to audio-in.liveatc.net:8010/xxx3_dir
Sep 09 08:35:32 art-atc-1 6c2bdf4f4886[369]: Trying to reconnect to audio-in.liveatc.net:8010/xxx3_dir...
Sep 09 08:35:37 art-atc-1 6c2bdf4f4886[369]: Could not connect to audio-in.liveatc.net:8010/xxx3_dir
Sep 09 08:35:47 art-atc-1 6c2bdf4f4886[369]: Trying to reconnect to audio-in.liveatc.net:8010/xxx3_dir...
Sep 09 08:35:51 art-atc-1 6c2bdf4f4886[369]: Could not connect to audio-in.liveatc.net:8010/xxx3_dir
Sep 09 08:35:53 art-atc-1 6c2bdf4f4886[369]: Exceeded max backlog for audio-in.liveatc.net:8010/xxx3_del, disconnecting
Sep 09 08:35:53 art-atc-1 6c2bdf4f4886[369]: Lost connection to audio-in.liveatc.net:8010/xxx3_del
Sep 09 08:36:00 art-atc-1 6c2bdf4f4886[369]: Lost connection to audio-in.liveatc.net:8010/xxx3_gnd_s
Sep 09 08:36:02 art-atc-1 6c2bdf4f4886[369]: Trying to reconnect to audio-in.liveatc.net:8010/xxx3_del...
Sep 09 08:36:06 art-atc-1 6c2bdf4f4886[369]: Could not connect to audio-in.liveatc.net:8010/xxx3_del
Sep 09 08:36:06 art-atc-1 6c2bdf4f4886[369]: Trying to reconnect to audio-in.liveatc.net:8010/xxx3_dir...
Sep 09 08:36:12 art-atc-1 6c2bdf4f4886[369]: Could not connect to audio-in.liveatc.net:8010/xxx3_dir
Sep 09 08:36:12 art-atc-1 6c2bdf4f4886[369]: Trying to reconnect to audio-in.liveatc.net:8010/xxx3_gnd_s...
Sep 09 08:36:17 art-atc-1 6c2bdf4f4886[369]: Could not connect to audio-in.liveatc.net:8010/xxx3_gnd_s
Sep 09 08:36:27 art-atc-1 6c2bdf4f4886[369]: Trying to reconnect to audio-in.liveatc.net:8010/xxx3_del...
Sep 09 08:36:31 art-atc-1 6c2bdf4f4886[369]: Could not connect to audio-in.liveatc.net:8010/xxx3_del
Sep 09 08:36:31 art-atc-1 6c2bdf4f4886[369]: Trying to reconnect to audio-in.liveatc.net:8010/xxx3_dir...
Sep 09 08:36:31 art-atc-1 6c2bdf4f4886[369]: Connecting to audio-in.liveatc.net:8010/xxx3_dir...
Sep 09 08:36:33 art-atc-1 6c2bdf4f4886[369]: Connected to audio-in.liveatc.net:8010/xxx3_dir
Sep 09 08:36:34 art-atc-1 6c2bdf4f4886[369]: Trying to reconnect to audio-in.liveatc.net:8010/xxx3_gnd_s...
Sep 09 08:36:34 art-atc-1 6c2bdf4f4886[369]: Connecting to audio-in.liveatc.net:8010/xxx3_gnd_s...
Sep 09 08:36:36 art-atc-1 6c2bdf4f4886[369]: Connected to audio-in.liveatc.net:8010/xxx3_gnd_s
Sep 09 08:36:46 art-atc-1 6c2bdf4f4886[369]: Trying to reconnect to audio-in.liveatc.net:8010/xxx3_del...
Sep 09 08:36:46 art-atc-1 6c2bdf4f4886[369]: Connecting to audio-in.liveatc.net:8010/xxx3_del...
Sep 09 08:36:48 art-atc-1 6c2bdf4f4886[369]: Connected to audio-in.liveatc.net:8010/xxx3_del
Sep 09 08:45:19 art-atc-1 6c2bdf4f4886[369]: Writing to /archives/dir/dir_20190909_08.mp3
szpajder commented 5 years ago

Thanks for the feedback. Give it some time - it's quite probable that it didn't hit the mentioned corner case yet.

danmilon commented 5 years ago

Got some weird behaviour again. Generally keep in mind the networking on the host running rtlsdr-airband is very bad, hence all the issues.

LiveATC monitoring says it's down, but rtlsdr-airband thinks it's fine. Here are the logs, since the time it is reporting down.

Oct 08 08:00:28 art-atc-1 6c2bdf4f4886[359]: Writing to /archives/twr1/twr1_20191008_08.mp3
Oct 08 08:01:05 art-atc-1 6c2bdf4f4886[359]: Writing to /archives/dir/dir_20191008_08.mp3
Oct 08 09:00:00 art-atc-1 6c2bdf4f4886[359]: Writing to /archives/dir/dir_20191008_09.mp3
Oct 08 09:00:00 art-atc-1 6c2bdf4f4886[359]: Writing to /archives/gnd_n/gnd_n_20191008_09.mp3
Oct 08 09:00:00 art-atc-1 6c2bdf4f4886[359]: Writing to /archives/gnd_s/gnd_s_20191008_09.mp3
Oct 08 09:00:20 art-atc-1 6c2bdf4f4886[359]: Writing to /archives/twr1/twr1_20191008_09.mp3
Oct 08 09:01:47 art-atc-1 6c2bdf4f4886[359]: Writing to /archives/del/del_20191008_09.mp3
Oct 08 09:05:57 art-atc-1 6c2bdf4f4886[359]: Writing to /archives/twr2/twr2_20191008_09.mp3
Oct 08 09:38:11 art-atc-1 6c2bdf4f4886[359]: Lost connection to audio-in.liveatc.net:8010/xxx_twr2
Oct 08 09:38:14 art-atc-1 6c2bdf4f4886[359]: Trying to reconnect to audio-in.liveatc.net:8010/xxx_twr2...
Oct 08 09:38:14 art-atc-1 6c2bdf4f4886[359]: Connecting to audio-in.liveatc.net:8010/xxx_twr2...
Oct 08 09:38:21 art-atc-1 6c2bdf4f4886[359]: Connected to audio-in.liveatc.net:8010/xxx_twr2
Oct 08 09:43:53 art-atc-1 6c2bdf4f4886[359]: Lost connection to audio-in.liveatc.net:8010/xxx_twr1
Oct 08 09:44:01 art-atc-1 6c2bdf4f4886[359]: Trying to reconnect to audio-in.liveatc.net:8010/xxx_twr1...
Oct 08 09:44:03 art-atc-1 6c2bdf4f4886[359]: Connecting to audio-in.liveatc.net:8010/xxx_twr1...
Oct 08 09:44:10 art-atc-1 6c2bdf4f4886[359]: Connected to audio-in.liveatc.net:8010/xxx_twr1
Oct 08 09:52:28 art-atc-1 6c2bdf4f4886[359]: Lost connection to audio-in.liveatc.net:8010/xxx_del
Oct 08 09:52:29 art-atc-1 6c2bdf4f4886[359]: Lost connection to audio-in.liveatc.net:8010/xxx_dir
Oct 08 09:52:29 art-atc-1 6c2bdf4f4886[359]: Lost connection to audio-in.liveatc.net:8010/xxx_gnd_n
Oct 08 09:52:30 art-atc-1 6c2bdf4f4886[359]: Lost connection to audio-in.liveatc.net:8010/xxx_twr2
Oct 08 09:52:30 art-atc-1 6c2bdf4f4886[359]: Trying to reconnect to audio-in.liveatc.net:8010/xxx_del...
Oct 08 09:52:31 art-atc-1 6c2bdf4f4886[359]: Lost connection to audio-in.liveatc.net:8010/xxx_gnd_s
Oct 08 09:52:32 art-atc-1 6c2bdf4f4886[359]: Connecting to audio-in.liveatc.net:8010/xxx_del...
Oct 08 09:52:37 art-atc-1 6c2bdf4f4886[359]: Connected to audio-in.liveatc.net:8010/xxx_del
Oct 08 09:52:37 art-atc-1 6c2bdf4f4886[359]: Trying to reconnect to audio-in.liveatc.net:8010/xxx_dir...
Oct 08 09:52:42 art-atc-1 6c2bdf4f4886[359]: Connecting to audio-in.liveatc.net:8010/xxx_dir...
Oct 08 09:52:45 art-atc-1 6c2bdf4f4886[359]: Connected to audio-in.liveatc.net:8010/xxx_dir
Oct 08 09:52:45 art-atc-1 6c2bdf4f4886[359]: Trying to reconnect to audio-in.liveatc.net:8010/xxx_gnd_n...
Oct 08 09:52:50 art-atc-1 6c2bdf4f4886[359]: Connecting to audio-in.liveatc.net:8010/xxx_gnd_n...
Oct 08 09:53:01 art-atc-1 6c2bdf4f4886[359]: Exceeded max backlog for audio-in.liveatc.net:8010/xxx_twr1, disconnecting
Oct 08 09:53:01 art-atc-1 6c2bdf4f4886[359]: Lost connection to audio-in.liveatc.net:8010/xxx_twr1
Oct 08 09:53:04 art-atc-1 6c2bdf4f4886[359]: Connected to audio-in.liveatc.net:8010/xxx_gnd_n
Oct 08 09:53:04 art-atc-1 6c2bdf4f4886[359]: Trying to reconnect to audio-in.liveatc.net:8010/xxx_gnd_s...
Oct 08 09:53:04 art-atc-1 6c2bdf4f4886[359]: Connecting to audio-in.liveatc.net:8010/xxx_gnd_s...
Oct 08 09:53:08 art-atc-1 6c2bdf4f4886[359]: Connected to audio-in.liveatc.net:8010/xxx_gnd_s
Oct 08 09:53:08 art-atc-1 6c2bdf4f4886[359]: Trying to reconnect to audio-in.liveatc.net:8010/xxx_twr2...
Oct 08 09:53:08 art-atc-1 6c2bdf4f4886[359]: Connecting to audio-in.liveatc.net:8010/xxx_twr2...
Oct 08 09:53:16 art-atc-1 6c2bdf4f4886[359]: Connected to audio-in.liveatc.net:8010/xxx_twr2
Oct 08 09:53:26 art-atc-1 6c2bdf4f4886[359]: Trying to reconnect to audio-in.liveatc.net:8010/xxx_twr1...
Oct 08 09:53:29 art-atc-1 6c2bdf4f4886[359]: Connecting to audio-in.liveatc.net:8010/xxx_twr1...
Oct 08 09:53:38 art-atc-1 6c2bdf4f4886[359]: Connected to audio-in.liveatc.net:8010/xxx_twr1
Oct 08 09:54:15 art-atc-1 6c2bdf4f4886[359]: Lost connection to audio-in.liveatc.net:8010/xxx_dir
Oct 08 09:54:19 art-atc-1 6c2bdf4f4886[359]: Trying to reconnect to audio-in.liveatc.net:8010/xxx_dir...
Oct 08 09:54:19 art-atc-1 6c2bdf4f4886[359]: Connecting to audio-in.liveatc.net:8010/xxx_dir...
Oct 08 09:54:21 art-atc-1 6c2bdf4f4886[359]: Connected to audio-in.liveatc.net:8010/xxx_dir
Oct 08 10:00:00 art-atc-1 6c2bdf4f4886[359]: Writing to /archives/twr1/twr1_20191008_10.mp3
Oct 08 10:00:00 art-atc-1 6c2bdf4f4886[359]: Writing to /archives/twr2/twr2_20191008_10.mp3
Oct 08 10:00:00 art-atc-1 6c2bdf4f4886[359]: Writing to /archives/gnd_n/gnd_n_20191008_10.mp3
Oct 08 10:00:00 art-atc-1 6c2bdf4f4886[359]: Writing to /archives/gnd_s/gnd_s_20191008_10.mp3
Oct 08 10:01:03 art-atc-1 6c2bdf4f4886[359]: Writing to /archives/del/del_20191008_10.mp3
Oct 08 10:04:20 art-atc-1 6c2bdf4f4886[359]: Lost connection to audio-in.liveatc.net:8010/xxx_twr2
Oct 08 10:04:22 art-atc-1 6c2bdf4f4886[359]: Trying to reconnect to audio-in.liveatc.net:8010/xxx_twr2...
Oct 08 10:04:27 art-atc-1 6c2bdf4f4886[359]: Connecting to audio-in.liveatc.net:8010/xxx_twr2...
Oct 08 10:04:32 art-atc-1 6c2bdf4f4886[359]: Connected to audio-in.liveatc.net:8010/xxx_twr2
Oct 08 10:07:18 art-atc-1 6c2bdf4f4886[359]: Lost connection to audio-in.liveatc.net:8010/xxx_dir
Oct 08 10:07:22 art-atc-1 6c2bdf4f4886[359]: Trying to reconnect to audio-in.liveatc.net:8010/xxx_dir...
Oct 08 10:07:22 art-atc-1 6c2bdf4f4886[359]: Connecting to audio-in.liveatc.net:8010/xxx_dir...
Oct 08 10:07:30 art-atc-1 6c2bdf4f4886[359]: Connected to audio-in.liveatc.net:8010/xxx_dir
Oct 08 10:15:57 art-atc-1 6c2bdf4f4886[359]: Lost connection to audio-in.liveatc.net:8010/xxx_del
Oct 08 10:15:59 art-atc-1 6c2bdf4f4886[359]: Trying to reconnect to audio-in.liveatc.net:8010/xxx_del...
Oct 08 10:16:02 art-atc-1 6c2bdf4f4886[359]: Connecting to audio-in.liveatc.net:8010/xxx_del...
Oct 08 10:16:04 art-atc-1 6c2bdf4f4886[359]: Connected to audio-in.liveatc.net:8010/xxx_del
Oct 08 10:22:42 art-atc-1 6c2bdf4f4886[359]: Lost connection to audio-in.liveatc.net:8010/xxx_gnd_n
Oct 08 10:22:44 art-atc-1 6c2bdf4f4886[359]: Trying to reconnect to audio-in.liveatc.net:8010/xxx_gnd_n...
Oct 08 10:22:49 art-atc-1 6c2bdf4f4886[359]: Connecting to audio-in.liveatc.net:8010/xxx_gnd_n...
Oct 08 10:22:53 art-atc-1 6c2bdf4f4886[359]: Connected to audio-in.liveatc.net:8010/xxx_gnd_n
Oct 08 10:23:55 art-atc-1 6c2bdf4f4886[359]: Lost connection to audio-in.liveatc.net:8010/xxx_twr2
Oct 08 10:24:03 art-atc-1 6c2bdf4f4886[359]: Trying to reconnect to audio-in.liveatc.net:8010/xxx_twr2...
Oct 08 10:24:03 art-atc-1 6c2bdf4f4886[359]: Connecting to audio-in.liveatc.net:8010/xxx_twr2...
Oct 08 10:24:10 art-atc-1 6c2bdf4f4886[359]: Connected to audio-in.liveatc.net:8010/xxx_twr2
Oct 08 10:34:45 art-atc-1 6c2bdf4f4886[359]: Lost connection to audio-in.liveatc.net:8010/xxx_del
Oct 08 10:34:50 art-atc-1 6c2bdf4f4886[359]: Trying to reconnect to audio-in.liveatc.net:8010/xxx_del...
Oct 08 10:34:53 art-atc-1 6c2bdf4f4886[359]: Connecting to audio-in.liveatc.net:8010/xxx_del...
Oct 08 10:35:23 art-atc-1 6c2bdf4f4886[359]: Could not connect to audio-in.liveatc.net:8010/xxx_del
Oct 08 10:35:33 art-atc-1 6c2bdf4f4886[359]: Trying to reconnect to audio-in.liveatc.net:8010/xxx_del...
Oct 08 10:35:35 art-atc-1 6c2bdf4f4886[359]: Connecting to audio-in.liveatc.net:8010/xxx_del...
Oct 08 10:35:42 art-atc-1 6c2bdf4f4886[359]: Connected to audio-in.liveatc.net:8010/xxx_del
Oct 08 10:48:52 art-atc-1 6c2bdf4f4886[359]: Lost connection to audio-in.liveatc.net:8010/xxx_gnd_s
Oct 08 10:48:52 art-atc-1 6c2bdf4f4886[359]: Trying to reconnect to audio-in.liveatc.net:8010/xxx_gnd_s...
Oct 08 10:48:56 art-atc-1 6c2bdf4f4886[359]: Lost connection to audio-in.liveatc.net:8010/xxx_del
Oct 08 10:48:57 art-atc-1 6c2bdf4f4886[359]: Connecting to audio-in.liveatc.net:8010/xxx_gnd_s...
Oct 08 10:49:02 art-atc-1 6c2bdf4f4886[359]: Connected to audio-in.liveatc.net:8010/xxx_gnd_s
Oct 08 10:49:12 art-atc-1 6c2bdf4f4886[359]: Trying to reconnect to audio-in.liveatc.net:8010/xxx_del...
Oct 08 10:49:17 art-atc-1 6c2bdf4f4886[359]: Connecting to audio-in.liveatc.net:8010/xxx_del...
Oct 08 10:49:24 art-atc-1 6c2bdf4f4886[359]: Could not connect to audio-in.liveatc.net:8010/xxx_del
Oct 08 10:49:34 art-atc-1 6c2bdf4f4886[359]: Trying to reconnect to audio-in.liveatc.net:8010/xxx_del...
Oct 08 10:49:34 art-atc-1 6c2bdf4f4886[359]: Connecting to audio-in.liveatc.net:8010/xxx_del...
Oct 08 10:49:39 art-atc-1 6c2bdf4f4886[359]: Connected to audio-in.liveatc.net:8010/xxx_del
Oct 08 10:52:14 art-atc-1 6c2bdf4f4886[359]: Lost connection to audio-in.liveatc.net:8010/xxx_twr1
Oct 08 10:52:16 art-atc-1 6c2bdf4f4886[359]: Lost connection to audio-in.liveatc.net:8010/xxx_twr2
Oct 08 10:52:19 art-atc-1 6c2bdf4f4886[359]: Trying to reconnect to audio-in.liveatc.net:8010/xxx_twr1...
Oct 08 10:52:24 art-atc-1 6c2bdf4f4886[359]: Connecting to audio-in.liveatc.net:8010/xxx_twr1...
Oct 08 10:52:33 art-atc-1 6c2bdf4f4886[359]: Connected to audio-in.liveatc.net:8010/xxx_twr1
Oct 08 10:52:33 art-atc-1 6c2bdf4f4886[359]: Trying to reconnect to audio-in.liveatc.net:8010/xxx_twr2...
Oct 08 10:52:36 art-atc-1 6c2bdf4f4886[359]: Connecting to audio-in.liveatc.net:8010/xxx_twr2...
Oct 08 10:52:42 art-atc-1 6c2bdf4f4886[359]: Could not connect to audio-in.liveatc.net:8010/xxx_twr2
Oct 08 10:52:52 art-atc-1 6c2bdf4f4886[359]: Trying to reconnect to audio-in.liveatc.net:8010/xxx_twr2...
Oct 08 10:52:54 art-atc-1 6c2bdf4f4886[359]: Connecting to audio-in.liveatc.net:8010/xxx_twr2...
Oct 08 10:53:13 art-atc-1 6c2bdf4f4886[359]: Connected to audio-in.liveatc.net:8010/xxx_twr2
Oct 08 10:55:14 art-atc-1 6c2bdf4f4886[359]: Lost connection to audio-in.liveatc.net:8010/xxx_del
Oct 08 10:55:23 art-atc-1 6c2bdf4f4886[359]: Trying to reconnect to audio-in.liveatc.net:8010/xxx_del...
Oct 08 10:55:24 art-atc-1 6c2bdf4f4886[359]: Connecting to audio-in.liveatc.net:8010/xxx_del...
Oct 08 10:55:31 art-atc-1 6c2bdf4f4886[359]: Connected to audio-in.liveatc.net:8010/xxx_del
Oct 08 11:00:00 art-atc-1 6c2bdf4f4886[359]: Writing to /archives/twr2/twr2_20191008_11.mp3
Oct 08 11:00:15 art-atc-1 6c2bdf4f4886[359]: Writing to /archives/twr1/twr1_20191008_11.mp3

So according to the logs, it has not detected the connection going down.

netstat says there's no connection from rtl_airband:

$ ps auxf | grep rtl_airband
root      1332 14.8  2.1  47768 20760 ?        Ssl  Oct07 369:00  |   |   \_ rtl_airband -Fec /rtl_airband.conf
$ sudo netstat -pa | grep -e 1332 -e airband
<nothing>
$ sudo ls -l /proc/1332/fd/
total 0
lr-x------ 1 root root 64 Oct  7 16:03 0 -> pipe:[13219]
l-wx------ 1 root root 64 Oct  7 16:03 1 -> pipe:[13220]
lrwx------ 1 root root 64 Oct  9 09:18 10 -> anon_inode:[timerfd]
lrwx------ 1 root root 64 Oct  9 09:18 11 -> /dev/bus/usb/001/004
lrwx------ 1 root root 64 Oct  9 09:18 12 -> socket:[14441836]
lrwx------ 1 root root 64 Oct  9 09:18 13 -> socket:[14648795]
lrwx------ 1 root root 64 Oct  9 09:18 14 -> socket:[15040602]
lr-x------ 1 root root 64 Oct  9 09:18 15 -> pipe:[18245]
l-wx------ 1 root root 64 Oct  9 09:18 16 -> pipe:[18245]
lrwx------ 1 root root 64 Oct  9 09:18 17 -> anon_inode:[timerfd]
lrwx------ 1 root root 64 Oct  9 09:18 18 -> /dev/bus/usb/001/007
lrwx------ 1 root root 64 Oct  9 09:18 19 -> socket:[15049572]
l-wx------ 1 root root 64 Oct  7 16:03 2 -> pipe:[13221]
lr-x------ 1 root root 64 Oct  9 09:18 20 -> pipe:[16712]
l-wx------ 1 root root 64 Oct  9 09:18 21 -> pipe:[16712]
lrwx------ 1 root root 64 Oct  9 09:18 22 -> anon_inode:[timerfd]
lrwx------ 1 root root 64 Oct  9 09:18 23 -> /dev/bus/usb/001/005
lr-x------ 1 root root 64 Oct  9 09:18 24 -> /dev/vcio
lrwx------ 1 root root 64 Oct  9 09:18 25 -> /archives/gnd_n/gnd_n_20191008_10.mp3
lrwx------ 1 root root 64 Oct  9 09:18 26 -> /archives/gnd_s/gnd_s_20191008_10.mp3
lrwx------ 1 root root 64 Oct  9 09:18 27 -> /archives/twr2/twr2_20191008_11.mp3
lrwx------ 1 root root 64 Oct  9 09:18 28 -> /archives/del/del_20191008_10.mp3
lrwx------ 1 root root 64 Oct  9 09:18 29 -> /archives/twr1/twr1_20191008_11.mp3
lrwx------ 1 root root 64 Oct  9 09:18 3 -> socket:[14987222]
lrwx------ 1 root root 64 Oct  9 09:18 30 -> /archives/dir/dir_20191008_09.mp3
lr-x------ 1 root root 64 Oct  9 09:18 31 -> /sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.5/speed
lrwx------ 1 root root 64 Oct  9 09:18 4 -> socket:[15081487]
lrwx------ 1 root root 64 Oct  9 09:18 5 -> socket:[17561]
lr-x------ 1 root root 64 Oct  9 09:18 6 -> pipe:[17562]
l-wx------ 1 root root 64 Oct  9 09:18 7 -> pipe:[17562]
lr-x------ 1 root root 64 Oct  9 09:18 8 -> pipe:[17563]
l-wx------ 1 root root 64 Oct  9 09:18 9 -> pipe:[17563]

And strace is too silent.

$ sudo strace -frp 1332
strace: Process 1332 attached with 7 threads
[pid  2172]      0.000000 futex(0x76f42f60, FUTEX_WAIT_PRIVATE, 2147483653, NULL <unfinished ...>
[pid  2171]      0.000322 nanosleep({tv_sec=3, tv_nsec=656552707},  <unfinished ...>
[pid  2170]      0.000534 futex(0xaa636c, FUTEX_WAIT_PRIVATE, 1073741838, NULL <unfinished ...>
[pid  2132]      0.000502 futex(0x76f42f60, FUTEX_WAIT_PRIVATE, 2147483653, NULL <unfinished ...>
[pid  2044]      0.000311 futex(0x76f42f60, FUTEX_WAIT_PRIVATE, 2147483653, NULL <unfinished ...>
[pid  2034]      0.000358 futex(0x76f42f60, FUTEX_WAIT_PRIVATE, 2147483653, NULL <unfinished ...>
[pid  1332]      0.000347 futex(0x769394b8, FUTEX_WAIT_PRIVATE, 2147483664, NULL <unfinished ...>
[pid  2171]      3.653717 <... nanosleep resumed> 0x755fbce0) = 0
[pid  2171]      0.000536 nanosleep({tv_sec=10, tv_nsec=0}, 0x755fbce0) = 0
[pid  2171]     10.000327 nanosleep({tv_sec=10, tv_nsec=0}, 0x755fbce0) = 0
[pid  2171]     10.000383 nanosleep({tv_sec=10, tv_nsec=0}, 10x755fbce0) = 0
[pid  2171]     10.000422 nanosleep({tv_sec=10, tv_nsec=0}, 0x755fbce0) = 0
[pid  2171]     10.000467 nanosleep({tv_sec=10, tv_nsec=0},

only nanosleep and stuck futex calls. Maybe it's stuck acquiring a lock? I just thought I should've captured a coredump, but I restarted it already.

hamav8tor commented 5 years ago

An upstream ISP was doing maintenance today from 0500-0900 UTC so there was periodic flapping as network routes converged.

danmilon commented 5 years ago

Interesting, although the feeds were reported down since ~Oct 08th 10:00 UTC.

hamav8tor commented 5 years ago

Then likely a different issue.

szpajder commented 4 years ago

Any news on this?

Does it still misbehave and require manual actions after the fix mentioned in https://github.com/szpajder/RTLSDR-Airband/issues/133#issuecomment-528555254 went in?