[ERROR] (Net::ReadTimeout) "Net::ReadTimeout with #<Socket:fd 7>"

[gbp]

Recurring error with the poller started 20th Jan

A Net::ReadTimeout occurred in background at 2023-01-20 16:29:40 +0000 :

  Net::ReadTimeout with #<Socket:fd 7>
  /opt/rbenv/versions/3.2.0/lib/ruby/3.2.0/net/protocol.rb:229:in `rbuf_fill'

-------------------------------
Backtrace:
-------------------------------

  /opt/rbenv/versions/3.2.0/lib/ruby/3.2.0/net/protocol.rb:229:in `rbuf_fill'
  /opt/rbenv/versions/3.2.0/lib/ruby/3.2.0/net/protocol.rb:199:in `readuntil'
  /opt/rbenv/versions/3.2.0/lib/ruby/3.2.0/net/protocol.rb:377:in `each_message_chunk'
  vendor/bundle/ruby/3.2.0/gems/net-pop-0.1.2/lib/net/pop.rb:958:in `block in retr'
  vendor/bundle/ruby/3.2.0/gems/net-pop-0.1.2/lib/net/pop.rb:1016:in `critical'
  vendor/bundle/ruby/3.2.0/gems/net-pop-0.1.2/lib/net/pop.rb:956:in `retr'
  vendor/bundle/ruby/3.2.0/gems/net-pop-0.1.2/lib/net/pop.rb:810:in `pop'
  lib/alaveteli_mail_poller.rb:59:in `get_mail'
  lib/alaveteli_mail_poller.rb:25:in `block (2 levels) in poll_for_incoming'
  vendor/bundle/ruby/3.2.0/gems/net-pop-0.1.2/lib/net/pop.rb:669:in `each'
  vendor/bundle/ruby/3.2.0/gems/net-pop-0.1.2/lib/net/pop.rb:669:in `each_mail'
  lib/alaveteli_mail_poller.rb:24:in `block in poll_for_incoming'
  lib/alaveteli_mail_poller.rb:114:in `start'
  lib/alaveteli_mail_poller.rb:23:in `poll_for_incoming'
  lib/alaveteli_mail_poller.rb:40:in `poll_for_incoming_loop'
  vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/commands/runner/runner_command.rb:46:in `<main>'
  vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/commands/runner/runner_command.rb:46:in `eval'
  vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/commands/runner/runner_command.rb:46:in `perform'
  vendor/bundle/ruby/3.2.0/gems/thor-1.2.1/lib/thor/command.rb:27:in `run'
  vendor/bundle/ruby/3.2.0/gems/thor-1.2.1/lib/thor/invocation.rb:127:in `invoke_command'
  vendor/bundle/ruby/3.2.0/gems/thor-1.2.1/lib/thor.rb:392:in `dispatch'
  vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/command/base.rb:87:in `perform'
  vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/command.rb:48:in `invoke'
  vendor/bundle/ruby/3.2.0/gems/railties-7.0.4.1/lib/rails/commands.rb:18:in `<top (required)>'
  bin/rails:4:in `require'
  bin/rails:4:in `<main>'

-------------------------------
Data:
-------------------------------

  * data: {:mail=>nil, :unique_id=>"000134e263356370"}

[gbp]

Was able to download the file which seemed stuck - although the unique ID changed from the original exception.

Setting a larger read timeout didn't seem to work. But loading the headers first did.

poller = AlaveteliMailPoller.new
poller.pop3.start(poller.settings[:user_name], poller.settings[:password])

poller.pop3.read_timeout = 300

m = poller.pop3.mails.first
id = m.unique_id # => 000134e263356370

m.pop # /opt/rbenv/versions/3.2.0/lib/ruby/3.2.0/net/protocol.rb:229:in `rbuf_fill': Net::ReadTimeout with #<Socket:fd 7> (Net::ReadTimeout)

poller.pop3.finish

# reconnect
poller.pop3.start(poller.settings[:user_name], poller.settings[:password])

m.header # => "Return-path: <010201 ..."

rawemail = m.pop # => "Return-path: <010201 ..."
File.open("#{id}.eml", 'w') { |f| f.write(rawemail) }
m.delete

poller.pop3.finish

Looking at the message it appears it had already been received so was a duplicate (with the same message ID) so maybe it wasn't deleted correctly after first being imported.

In IncomingMessageError there has been an uptick in errors recently:

irb(main):001:0> IncomingMessageError.pluck(:unique_id, :created_at, :retry_at)
=>
[["000222d259f21e3d", Tue, 17 Jul 2018 17:25:44.167518000 BST +01:00, Tue, 17 Jul 2018 17:55:44.159135000 BST +01:00],
 ["0002a5c559f21e3d", Mon, 06 Aug 2018 14:55:19.787780000 BST +01:00, Mon, 06 Aug 2018 15:25:19.779673000 BST +01:00],
 ["0004258359f21e3d", Mon, 17 Sep 2018 08:36:33.090389000 BST +01:00, nil],
 ["00034fa45c0f87ef", Tue, 20 Aug 2019 13:45:36.688001000 BST +01:00, Tue, 20 Aug 2019 14:15:36.674128000 BST +01:00],
 ["0004d7765c0f87ef", Mon, 03 Feb 2020 15:06:07.351801000 GMT +00:00, Mon, 03 Feb 2020 15:36:07.333386000 GMT +00:00],
 ["0007ae875c0f87ef", Sat, 09 Jan 2021 23:28:57.783525000 GMT +00:00, nil],
 ["0007ae885c0f87ef", Sat, 09 Jan 2021 23:29:01.153487000 GMT +00:00, Sat, 09 Jan 2021 23:59:00.861274000 GMT +00:00],
 ["000bcb755c0f87ef", Thu, 10 Feb 2022 18:13:28.352099000 GMT +00:00, Fri, 11 Feb 2022 00:03:47.214725000 GMT +00:00],
 ["000c12235c0f87ef", Sun, 06 Mar 2022 20:58:08.272515000 GMT +00:00, Sun, 06 Mar 2022 21:28:08.270297000 GMT +00:00],
 ["000c2c2e5c0f87ef", Mon, 14 Mar 2022 13:55:14.660659000 GMT +00:00, Mon, 14 Mar 2022 14:25:14.630991000 GMT +00:00],
 ["000aaaa75c0f87ef", Sun, 17 Oct 2021 22:44:11.358786000 BST +01:00, Mon, 18 Oct 2021 07:49:50.904358000 BST +01:00],
 ["000aaab25c0f87ef", Mon, 18 Oct 2021 06:50:17.181312000 BST +01:00, Mon, 18 Oct 2021 07:50:22.901795000 BST +01:00],
 ["000aaac05c0f87ef", Mon, 18 Oct 2021 07:37:28.261294000 BST +01:00, Mon, 18 Oct 2021 08:07:28.259308000 BST +01:00],
 ["000aaac55c0f87ef", Mon, 18 Oct 2021 07:39:40.338664000 BST +01:00, Mon, 18 Oct 2021 08:09:40.336601000 BST +01:00],
 ["000aaac85c0f87ef", Mon, 18 Oct 2021 07:46:05.122602000 BST +01:00, Mon, 18 Oct 2021 08:16:05.120514000 BST +01:00],
 ["000caa945c0f87ef", Wed, 27 Apr 2022 14:25:57.380230000 BST +01:00, Wed, 27 Apr 2022 14:55:57.377328000 BST +01:00],
 ["000ccc1a5c0f87ef", Wed, 11 May 2022 10:38:57.286535000 BST +01:00, Wed, 11 May 2022 11:08:57.283374000 BST +01:00],
 ["0000886263356370", Thu, 17 Nov 2022 17:58:17.939234000 GMT +00:00, Thu, 17 Nov 2022 18:28:17.923564000 GMT +00:00],
 ["0000b5cf63356370", Sat, 03 Dec 2022 12:57:22.030277000 GMT +00:00, Sat, 03 Dec 2022 13:27:21.997747000 GMT +00:00],
 ["0001133b63356370", Fri, 13 Jan 2023 09:25:23.383949000 GMT +00:00, Fri, 13 Jan 2023 09:55:23.365557000 GMT +00:00],
 ["0001138e63356370", Fri, 13 Jan 2023 10:15:41.192737000 GMT +00:00, Fri, 13 Jan 2023 10:45:41.186789000 GMT +00:00],
 ["000134e263356370", Fri, 20 Jan 2023 16:29:40.226382000 GMT +00:00, Fri, 20 Jan 2023 16:59:40.206681000 GMT +00:00],
 ["000138bd63356370", Mon, 23 Jan 2023 14:48:18.619603000 GMT +00:00, Mon, 23 Jan 2023 15:18:18.601351000 GMT +00:00],
 ["000139bb63356370", Mon, 23 Jan 2023 17:53:25.448236000 GMT +00:00, Mon, 23 Jan 2023 18:23:25.437146000 GMT +00:00],
 ["0001425e63356370", Thu, 26 Jan 2023 10:03:13.515878000 GMT +00:00, Thu, 26 Jan 2023 10:33:13.506478000 GMT +00:00],
 ["0001452463356370", Thu, 26 Jan 2023 16:28:50.340706000 GMT +00:00, Thu, 26 Jan 2023 16:58:50.336257000 GMT +00:00],
 ["00014f9a63356370", Mon, 30 Jan 2023 15:50:48.286096000 GMT +00:00, Mon, 30 Jan 2023 16:20:48.281837000 GMT +00:00],
 ["00013b8e63356370", Tue, 24 Jan 2023 12:20:28.347577000 GMT +00:00, Tue, 31 Jan 2023 12:17:58.686651000 GMT +00:00]]

Most of these retry once and then succeed but this 00013b8e63356370 has been trying and failing for a week.

[gbp]

@sagepe we're still seeing this error.

Am wondering if this could be similar to #4526 and the linked sysadmin issue https://github.com/mysociety/sysadmin/issues/1036

[gbp]

Still seeing this errors at regular frequency.

I have confirmed this isn't an app issue using a separate Ruby script with Ruby 3.2.

Rolling back to Ruby 2.7 the script works fine. Also tested and its fine on 3.0 and 3.1.

Between 3.0 and 3.1 the net-* libraries were extracted as a gem including net-pop.

Doing a bisect of upstream commits this one seems to be the first which is causing my script to fail.

So lets bisect net-protocol too, between 0.1.3 and 0.2.0 this commit was added and is the cause of our issue.

We should pin Alaveteli to net-protocol to 0.1.3 and report this issue upstream.