search

romanz / amodem

Audio MODEM Communication Library in Python
Other
965 stars 121 forks source link

IOError timeout #49

Closed YuliaMorzhova closed 3 years ago

YuliaMorzhova commented 3 years ago

Trying to use amodem with I/O redirection on Linux 5.4.0-73-generic #82~18.04.1-Ubuntu and python (Python 3.7.5) I've got the following timeout:

$file test_data
test_data: ASCII text, with no line terminators
$ cat test_data
1234567891234454

$ amodem send -vv -i test_data -o test.pcm
2021-06-16 09:26:30,136 INFO       Audio OFDM MODEM v1.15.1: 1.0 kb/s (2-QAM x 1 carriers) Fs=8.0 kHz                                   __main__.py:235
2021-06-16 09:26:30,141 INFO       Sending 0.800 seconds of training audio                                                              main.py:23
2021-06-16 09:26:30,141 INFO       Starting modulation                                                                                  main.py:28
2021-06-16 09:26:30,147 INFO       Sent 0.016 kB @ 0.209 seconds                                                                        main.py:33
2021-06-16 09:26:30,147 DEBUG      Finished I/O     __main__.py:266

$ amodem recv -vv -i test.pcm -o data_test
2021-06-16 09:27:07,608 INFO       Audio OFDM MODEM v1.15.1: 1.0 kb/s (2-QAM x 1 carriers) Fs=8.0 kHz                                   __main__.py:235
2021-06-16 09:27:07,608 DEBUG      Skipping 0.100 seconds                                                                               main.py:46
2021-06-16 09:27:07,609 INFO       Waiting for carrier tone: 2.0 kHz                                                                    main.py:53
2021-06-16 09:27:07,620 INFO       Carrier detected at ~150.0 ms @ 2.0 kHz                                                              detect.py:61
2021-06-16 09:27:07,620 DEBUG      Buffered 330 ms of audio                                                                             detect.py:63
2021-06-16 09:27:07,620 INFO       Carrier coherence: 100.000%                                                                          detect.py:94
2021-06-16 09:27:07,621 DEBUG      Carrier starts at 149.875 ms                                                                         detect.py:73
2021-06-16 09:27:07,622 INFO       Carrier symbols amplitude : 1.000                                                                    detect.py:105
2021-06-16 09:27:07,622 INFO       Frequency error: 0.000 ppm                                                                           detect.py:115
2021-06-16 09:27:07,622 DEBUG      Frequency correction: 0.000 ppm                                                                      main.py:57
2021-06-16 09:27:07,622 DEBUG      Gain correction: 1.000                                                                               main.py:60
2021-06-16 09:27:07,622 DEBUG      Receiving                                                                                            recv.py:161
2021-06-16 09:27:07,647 DEBUG      Prefix OK                                                                                            recv.py:50
2021-06-16 09:27:07,674 DEBUG      Training completed                                                                                   recv.py:73
2021-06-16 09:27:07,689 DEBUG        2.0 kHz: SNR = 305.91 dB                                                                           recv.py:95
2021-06-16 09:27:07,690 DEBUG      Training verified                                                                                    recv.py:99
2021-06-16 09:27:07,691 INFO       Starting demodulation                                                                                recv.py:130
2021-06-16 09:27:07,719 DEBUG      Good checksum: 7005c488                                                                              framing.py:32
2021-06-16 09:27:09,729 ERROR      Decoding failed                                                                                      main.py:67
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/amodem/main.py", line 64, in recv
    receiver.run(sampler, gain=1.0/amplitude, output=dst)
  File "/usr/local/lib/python3.7/dist-packages/amodem/recv.py", line 171, in run
    for frame in framing.decode_frames(bitstream):
  File "/usr/local/lib/python3.7/dist-packages/amodem/framing.py", line 122, in decode_frames
    for frame in framer.decode(_to_bytes(bits)):
  File "/usr/local/lib/python3.7/dist-packages/amodem/framing.py", line 58, in decode
    frame = _take_len(data, length)
  File "/usr/local/lib/python3.7/dist-packages/amodem/framing.py", line 76, in _take_len
    chunk = bytearray(itertools.islice(data, length))
  File "/usr/local/lib/python3.7/dist-packages/amodem/framing.py", line 116, in _to_bytes
    func=tuple, truncate=True):
  File "/usr/local/lib/python3.7/dist-packages/amodem/common.py", line 41, in iterate
    buf = list(itertools.islice(data, size))
  File "/usr/local/lib/python3.7/dist-packages/amodem/recv.py", line 131, in _demodulate
    for i, block_of_bits in enumerate(stream, 1):
  File "/usr/local/lib/python3.7/dist-packages/amodem/common.py", line 81, in izip
    yield tuple([next(iterable) for iterable in iterables])
  File "/usr/local/lib/python3.7/dist-packages/amodem/common.py", line 81, in <listcomp>
    yield tuple([next(iterable) for iterable in iterables])
  File "/usr/local/lib/python3.7/dist-packages/amodem/dsp.py", line 104, in decode
    for received in symbols:
  File "/usr/local/lib/python3.7/dist-packages/amodem/common.py", line 66, in icapture
    for i in iter(iterable):
  File "/usr/local/lib/python3.7/dist-packages/amodem/common.py", line 57, in _gen
    for item in it:
  File "/usr/local/lib/python3.7/dist-packages/amodem/dsp.py", line 33, in next
    frame = self.sampler.take(size=self.Nsym)
  File "/usr/local/lib/python3.7/dist-packages/amodem/sampling.py", line 74, in _take
    self.buff[-1] = next(self.src)  # throws StopIteration
  File "/usr/local/lib/python3.7/dist-packages/amodem/stream.py", line 42, in next
    raise IOError('timeout')
OSError: timeout
2021-06-16 09:27:09,731 DEBUG      Demodulated 0.026 kB @ 2.040 seconds (990.4% realtime)                                               recv.py:181
2021-06-16 09:27:09,731 INFO       Received 0.016 kB @ 2.040 seconds = 0.008 kB/s                                                       recv.py:185
2021-06-16 09:27:09,732 DEBUG      Finished I/O                                                                                         __main__.py:266

I tried all from Decoding failed #33 (amodem recv -vvv -l ALSA, and increase Reader.timeout from 2s to 30s) but the timeout still happening.

I noted that the timeout depends on symbols quantity in the test_data file. For instance with 16 symbols (123456789123445) there are no timeout (previous was 17)

m$ cat test_data
123456789123445
$ amodem send -vv -i test_data -o test.pcm
2021-06-16 09:35:02,973 INFO       Audio OFDM MODEM v1.15.1: 1.0 kb/s (2-QAM x 1 carriers) Fs=8.0 kHz                                   __main__.py:235
2021-06-16 09:35:02,978 INFO       Sending 0.800 seconds of training audio                                                              main.py:23
2021-06-16 09:35:02,978 INFO       Starting modulation                                                                                  main.py:28
2021-06-16 09:35:02,984 INFO       Sent 0.015 kB @ 0.201 seconds                                                                        main.py:33
2021-06-16 09:35:02,984 DEBUG      Finished I/O                                                                                         __main__.py:266
$ amodem recv -vv -i test.pcm -o data_test
2021-06-16 09:35:07,212 INFO       Audio OFDM MODEM v1.15.1: 1.0 kb/s (2-QAM x 1 carriers) Fs=8.0 kHz                                   __main__.py:235
2021-06-16 09:35:07,213 DEBUG      Skipping 0.100 seconds                                                                               main.py:46
2021-06-16 09:35:07,213 INFO       Waiting for carrier tone: 2.0 kHz                                                                    main.py:53
2021-06-16 09:35:07,224 INFO       Carrier detected at ~150.0 ms @ 2.0 kHz                                                              detect.py:61
2021-06-16 09:35:07,224 DEBUG      Buffered 330 ms of audio                                                                             detect.py:63
2021-06-16 09:35:07,225 INFO       Carrier coherence: 100.000%                                                                          detect.py:94
2021-06-16 09:35:07,225 DEBUG      Carrier starts at 149.875 ms                                                                         detect.py:73
2021-06-16 09:35:07,226 INFO       Carrier symbols amplitude : 1.000                                                                    detect.py:105
2021-06-16 09:35:07,227 INFO       Frequency error: 0.000 ppm                                                                           detect.py:115
2021-06-16 09:35:07,227 DEBUG      Frequency correction: 0.000 ppm                                                                      main.py:57
2021-06-16 09:35:07,227 DEBUG      Gain correction: 1.000                                                                               main.py:60
2021-06-16 09:35:07,227 DEBUG      Receiving                                                                                            recv.py:161
2021-06-16 09:35:07,251 DEBUG      Prefix OK                                                                                            recv.py:50
2021-06-16 09:35:07,278 DEBUG      Training completed                                                                                   recv.py:73
2021-06-16 09:35:07,292 DEBUG        2.0 kHz: SNR = 305.91 dB                                                                           recv.py:95
2021-06-16 09:35:07,293 DEBUG      Training verified                                                                                    recv.py:99
2021-06-16 09:35:07,294 INFO       Starting demodulation                                                                                recv.py:130
2021-06-16 09:35:07,321 DEBUG      Good checksum: 605a7717                                                                              framing.py:32
2021-06-16 09:35:07,328 DEBUG      Good checksum: 00000000                                                                              framing.py:32
2021-06-16 09:35:07,328 DEBUG      EOF frame detected                                                                                   framing.py:61
2021-06-16 09:35:07,328 DEBUG      Demodulated 0.025 kB @ 0.034 seconds (17.0% realtime)                                                recv.py:181
2021-06-16 09:35:07,328 INFO       Received 0.015 kB @ 0.034 seconds = 0.441 kB/s                                                       recv.py:185
2021-06-16 09:35:07,328 DEBUG      Finished I/O                                                                                         __main__.py:266
$ sha256sum test_data
edba68fe901b11e8827c8fe9d55887fdd651a77629f6e9c1f0fba5e8bef069c6  test_data
$ sha256sum data_test
edba68fe901b11e8827c8fe9d55887fdd651a77629f6e9c1f0fba5e8bef069c6  data_test

with 100 timeout, with 124 -no timeout... May be there is something with framing...

romanz commented 3 years ago

Many thanks for reporting this issue!

romanz commented 3 years ago

50 should work (tested on 17-byte sized file):

$ amodem send -vvv -i input.txt -o- | amodem recv -i- -vvvvv
2021-06-19 13:57:26,253 INFO       Audio OFDM MODEM v1.15.1: 1.0 kb/s (2-QAM x 1 carriers) Fs=8.0 kHz                                   __main__.py:235
2021-06-19 13:57:26,254 INFO       Audio OFDM MODEM v1.15.1: 1.0 kb/s (2-QAM x 1 carriers) Fs=8.0 kHz                                   __main__.py:235
2021-06-19 13:57:26,254 DEBUG      Skipping 0.100 seconds                                                                               main.py:46
2021-06-19 13:57:26,255 INFO       Sending 1.050 seconds of training audio                                                              main.py:23
2021-06-19 13:57:26,255 INFO       Starting modulation                                                                                  main.py:28
2021-06-19 13:57:26,255 INFO       Waiting for carrier tone: 2.0 kHz                                                                    main.py:53
2021-06-19 13:57:26,257 INFO       Sent 0.017 kB @ 0.217 seconds                                                                        main.py:32
2021-06-19 13:57:26,257 DEBUG      Finished I/O                                                                                         __main__.py:266
2021-06-19 13:57:26,262 INFO       Carrier detected at ~400.0 ms @ 2.0 kHz                                                              detect.py:60
2021-06-19 13:57:26,262 DEBUG      Buffered 580 ms of audio                                                                             detect.py:63
2021-06-19 13:57:26,262 INFO       Carrier coherence: 100.000%                                                                          detect.py:94
2021-06-19 13:57:26,262 DEBUG      Carrier starts at 399.875 ms                                                                         detect.py:73
2021-06-19 13:57:26,263 INFO       Carrier symbols amplitude : 1.000                                                                    detect.py:105
2021-06-19 13:57:26,263 INFO       Frequency error: 0.000 ppm                                                                           detect.py:115
2021-06-19 13:57:26,263 DEBUG      Frequency correction: 0.000 ppm                                                                      main.py:57
2021-06-19 13:57:26,263 DEBUG      Gain correction: 1.000                                                                               main.py:60
2021-06-19 13:57:26,263 DEBUG      Receiving                                                                                            recv.py:161
2021-06-19 13:57:26,275 DEBUG      Prefix OK                                                                                            recv.py:50
2021-06-19 13:57:26,289 DEBUG      Training completed                                                                                   recv.py:73
2021-06-19 13:57:26,299 DEBUG        2.0 kHz: SNR = 305.65 dB                                                                           recv.py:95
2021-06-19 13:57:26,299 DEBUG      Training verified                                                                                    recv.py:99
2021-06-19 13:57:26,300 INFO       Starting demodulation                                                                                recv.py:130
2021-06-19 13:57:26,316 DEBUG      Good checksum: 3fa43360                                                                              framing.py:32
2021-06-19 13:57:26,319 DEBUG      Good checksum: 00000000                                                                              framing.py:32
2021-06-19 13:57:26,319 DEBUG      EOF frame detected                                                                                   framing.py:61
123456789012345672021-06-19 13:57:26,319 DEBUG      Demodulated 0.027 kB @ 0.020 seconds (9.1% realtime)                                                 recv.py:179
2021-06-19 13:57:26,320 INFO       Received 0.017 kB @ 0.020 seconds = 0.863 kB/s                                                       recv.py:183
2021-06-19 13:57:26,320 DEBUG      Finished I/O                                                                                         __main__.py:266
YuliaMorzhova commented 3 years ago

Hello, thank you ! I tried from this branch and it works for me without any problems, so I tend to think this issue is solved and I close it. Once again thank you for your time and quick support!

romanz commented 3 years ago

Cool, happy to help :)