NNTP served by public-inbox stalled in Alpine 2.21.99

NNTP served by public-inbox stalled in Alpine 2.21.99

[Wang Kang]

[-- Attachment #1: Type: text/plain, Size: 891 bytes --]

Dear lists,

I was trying to read NNTP news served by public-inbox [1], for example 
[2] provided by Linux Kernel.

The index screen works fine. I can see the complete list of message titles 
on the index screen. However, when I press enter on any of the message to 
read the body of this news, the screen stucks for ever.

On the contrary, NNTP served by gmane, for example [3], works fine on 
alpine.

I have attached those two debug logs generated by `alpine -d 4`. Hope you 
can help solve this problem.


By the way, I can read [2] from w3m correctly:

    w3m nntp://nntp.lore.kernel.org/com.zx2c4.lists.wireguard


[1]: https://www.kernel.org/lore.html
[2]: nntp://nntp.lore.kernel.org/com.zx2c4.lists.wireguard
[3]: gmane.mail.public-inbox.general


Thank you.

-- 
Wang Kang
Blog: http://scateu.me
Fingerprint: 011F 0492 97D6 5D75 8AC4  6458 D43F 3CE2 3353 B7BD
HAM Callsign: BH1RLW

[-- Attachment #2: Type: text/plain, Size: 6704 bytes --]

IMAP 10:04:29 1/16 mm_log babble: Trying IP address [195.159.176.226]
IMAP DEBUG 10:04:29 1/16: 200 news.gmane.org InterNetNews NNRP server INN 2.5.4 ready (posting ok)
IMAP 10:04:29 1/16 mm_notify babble: -no folder-: news.gmane.org InterNetNews NNRP server INN 2.5.4 ready (posting ok)
IMAP DEBUG 10:04:29 1/16: LIST EXTENSIONS
IMAP DEBUG 10:04:30 1/16: 501 Unknown LIST keyword
IMAP DEBUG 10:04:30 1/16: MODE READER
IMAP DEBUG 10:04:30 1/16: 200 news.gmane.org InterNetNews NNRP server INN 2.5.4 ready (posting ok)
About to open folder "gmane.announce"    inbox is: "INBOX"
IMAP 10:04:34 1/16 mm_log babble: Reusing connection to blaine.gmane.org
IMAP DEBUG 10:04:34 1/16: GROUP gmane.announce
IMAP DEBUG 10:04:34 1/16: 211 25105 1 25341 gmane.announce
IMAP DEBUG 10:04:34 1/16: XHDR Date 23342-25341
IMAP DEBUG 10:04:34 1/16: 221 Header or metadata information for Date follows (from overview)
=== mm_exists(589,{blaine.gmane.org:119/nntp/readonly}#news.gmane.announce) called ===
IMAP 10:04:34 1/16 mm_notify babble: {blaine.gmane.org:119/nntp/readonly}#news.gmane.announce: [UNSEEN] 1 is first unseen message in gmane.announce
IMAP DEBUG 10:04:34 1/16: STAT
IMAP DEBUG 10:04:34 1/16: 223 1 <m3y9ansu4v.fsf@quimbies.gnus.org> status
Opened folder "{blaine.gmane.org:119/nntp/readonly}#news.gmane.announce" with 589 messages
IMAP DEBUG 10:04:34 1/16: STAT
IMAP DEBUG 10:04:34 1/16: 223 1 <m3y9ansu4v.fsf@quimbies.gnus.org> status
Sorting by Arrival
IMAP DEBUG 10:04:34 1/16: STAT
IMAP DEBUG 10:04:34 1/16: 223 1 <m3y9ansu4v.fsf@quimbies.gnus.org> status
First_sorted_flagged returning winner = 1


 ---- MAIL INDEX ----


 ---- INDEX MANAGER ----
IMAP DEBUG 10:04:34 1/16: XOVER 23343-24734
IMAP DEBUG 10:04:35 1/16: 224 Overview information for 23343-24734 follows

 - process_cmd(cmd=505) -


  -----  MAIL VIEW  -----
IMAP DEBUG 10:04:54 1/16: HEAD 23343
IMAP DEBUG 10:04:54 1/16: 221 23343 <E1ZCtLO-0007Ql-U1@plane.gmane.org> head
IMAP DEBUG 10:04:54 1/16: BODY 23343
IMAP DEBUG 10:04:54 1/16: 222 23343 <E1ZCtLO-0007Ql-U1@plane.gmane.org> body
-- gf_pipe: 
done.
-- gf_pipe: 
done.
-- gf_pipe: 
done.
-- gf_pipe: 
done.

 - process_cmd(cmd=504) -


 ---- MAIL INDEX ----


 ---- INDEX MANAGER ----

 - jump_to -
IMAP DEBUG 10:05:01 1/16: XOVER 25302-25341
IMAP DEBUG 10:05:01 1/16: 224 Overview information for 25302-25341 follows

 - process_cmd(cmd=505) -


  -----  MAIL VIEW  -----
IMAP DEBUG 10:05:03 1/16: HEAD 25341
IMAP DEBUG 10:05:03 1/16: 221 25341 <E1fClwp-0003FT-CO@blaine.gmane.org> head
IMAP DEBUG 10:05:03 1/16: BODY 25341
IMAP DEBUG 10:05:03 1/16: 222 25341 <E1fClwp-0003FT-CO@blaine.gmane.org> body
-- gf_pipe: 
done.
-- gf_pipe: 
done.
-- gf_pipe: 
done.
-- gf_pipe: 
done.

 - process_cmd(cmd=504) -


 ---- MAIL INDEX ----


 ---- INDEX MANAGER ----

 - process_cmd(cmd=507) -
MAIL_CMD: going to folder/collection menu
=== folder_screen called ====


    ---- FOLDER LISTER ----
IMAP DEBUG 10:05:12 1/16: 00000016 SEARCH 1:85,87:88,90:93,95:98 UNDELETED UNSEEN
IMAP DEBUG 10:05:12 1/16: * SEARCH 62 63 84 85 87 88 90 91 92 97 98
IMAP DEBUG 10:05:12 1/16: 00000016 OK Completed (11 msgs in 0.001 secs)
IMAP 10:05:12 1/16 mm_log babble: Trying IP address [195.159.176.226]
IMAP DEBUG 10:05:12 1/16: 200 news.gmane.org InterNetNews NNRP server INN 2.5.4 ready (posting ok)
IMAP 10:05:12 1/16 mm_notify babble: -no folder-: news.gmane.org InterNetNews NNRP server INN 2.5.4 ready (posting ok)
IMAP DEBUG 10:05:12 1/16: LIST EXTENSIONS
IMAP DEBUG 10:05:12 1/16: 501 Unknown LIST keyword
IMAP DEBUG 10:05:12 1/16: MODE READER
IMAP DEBUG 10:05:12 1/16: 200 news.gmane.org InterNetNews NNRP server INN 2.5.4 ready (posting ok)
About to open folder "gmane.comp.encryption.general"    inbox is: "INBOX"
expunge_and_close: "gmane.announce"
IMAP DEBUG 10:05:15 1/16: QUIT
IMAP DEBUG 10:05:15 1/16: 205 Bye!
IMAP 10:05:15 1/16 mm_log babble: Reusing connection to blaine.gmane.org
IMAP DEBUG 10:05:15 1/16: GROUP gmane.comp.encryption.general
IMAP DEBUG 10:05:15 1/16: 211 32812 1 32871 gmane.comp.encryption.general
IMAP DEBUG 10:05:15 1/16: XHDR Date 30872-32871
IMAP DEBUG 10:05:15 1/16: 221 Header or metadata information for Date follows (from overview)
=== mm_exists(2000,{blaine.gmane.org:119/nntp/readonly}#news.gmane.comp.encryption.general) called ===
IMAP 10:05:16 1/16 mm_notify babble: {blaine.gmane.org:119/nntp/readonly}#news.gmane.comp.encryption.general: [UNSEEN] 1 is first unseen message in gmane.comp.encryption.general
IMAP DEBUG 10:05:16 1/16: STAT
IMAP DEBUG 10:05:16 1/16: 223 1 <l6bbfuscf6ap2gi64onbibi98vr9rusi29@4ax.com> status
Opened folder "{blaine.gmane.org:119/nntp/readonly}#news.gmane.comp.encryption.general" with 2000 messages
IMAP DEBUG 10:05:16 1/16: STAT
IMAP DEBUG 10:05:17 1/16: 223 1 <l6bbfuscf6ap2gi64onbibi98vr9rusi29@4ax.com> status
Sorting by Arrival
IMAP DEBUG 10:05:17 1/16: STAT
IMAP DEBUG 10:05:17 1/16: 223 1 <l6bbfuscf6ap2gi64onbibi98vr9rusi29@4ax.com> status
First_sorted_flagged returning winner = 725


 ---- MAIL INDEX ----


 ---- INDEX MANAGER ----
IMAP DEBUG 10:05:17 1/16: XOVER 31547-31566
IMAP DEBUG 10:05:17 1/16: 224 Overview information for 31547-31566 follows
IMAP DEBUG 10:05:17 1/16: XOVER 31568-31600
IMAP DEBUG 10:05:17 1/16: 224 Overview information for 31568-31600 follows
IMAP DEBUG 10:05:17 1/16: XOVER 31602-31609
IMAP DEBUG 10:05:17 1/16: 224 Overview information for 31602-31609 follows

 - process_cmd(cmd=505) -


  -----  MAIL VIEW  -----
IMAP DEBUG 10:05:20 1/16: HEAD 31602
IMAP DEBUG 10:05:20 1/16: 221 31602 <E1eX8p1-0006kA-P0@elasmtp-masked.atl.sa.earthlink.net> head
IMAP DEBUG 10:05:20 1/16: BODY 31602
IMAP DEBUG 10:05:21 1/16: 222 31602 <E1eX8p1-0006kA-P0@elasmtp-masked.atl.sa.earthlink.net> body
-- gf_pipe: 
done.
-- gf_pipe: 
done.
-- gf_pipe: 
done.
-- gf_pipe: 
done.
IMAP DEBUG 10:06:17 1/16: STAT
IMAP DEBUG 10:06:17 1/16: 223 31602 <E1eX8p1-0006kA-P0@elasmtp-masked.atl.sa.earthlink.net> status
IMAP DEBUG 10:06:17 1/16: 00000017 NOOP
IMAP DEBUG 10:06:17 1/16: 00000017 OK Completed
IMAP DEBUG 10:07:21 1/16: STAT
IMAP DEBUG 10:07:21 1/16: 223 31602 <E1eX8p1-0006kA-P0@elasmtp-masked.atl.sa.earthlink.net> status
Checkpoint: 10:07:21.588295  Since 1st change: 220 secs  idle: 121 secs
IMAP DEBUG 10:07:21 1/16: 00000018 CHECK
IMAP DEBUG 10:07:21 1/16: 00000018 OK Completed
IMAP 10:07:21 1/16 mm_log babble: Completed
Checkpoint complete: 10:07:21.658799
IMAP DEBUG 10:08:25 1/16: STAT
IMAP DEBUG 10:08:25 1/16: 223 31602 <E1eX8p1-0006kA-P0@elasmtp-masked.atl.sa.earthlink.net> status
IMAP DEBUG 10:08:25 1/16: 00000019 NOOP

[-- Attachment #3: Type: text/plain, Size: 2805 bytes --]

IMAP 10:10:05 1/16 mm_log babble: Trying IP address [54.189.247.149]
IMAP DEBUG 10:10:05 1/16: 201 server ready - post via email
IMAP DEBUG 10:10:05 1/16: LIST EXTENSIONS
IMAP DEBUG 10:10:05 1/16: 501 command syntax error

IMAP DEBUG 10:10:05 1/16: MODE READER
IMAP DEBUG 10:10:05 1/16: 201 Posting prohibited
About to open folder "com.zx2c4.lists.wireguard"    inbox is: "INBOX"
IMAP 10:10:07 1/16 mm_log babble: Reusing connection to korg-lkml-1-news-lb-839eef9f3a4cef4e.elb.us-west-2.amazonaws.com
IMAP DEBUG 10:10:07 1/16: GROUP com.zx2c4.lists.wireguard
IMAP DEBUG 10:10:07 1/16: 211 3774 1 3775 com.zx2c4.lists.wireguard
IMAP DEBUG 10:10:07 1/16: LISTGROUP com.zx2c4.lists.wireguard
IMAP DEBUG 10:10:07 1/16: 211 3774 1 3775 com.zx2c4.lists.wireguard
=== mm_exists(2000,{korg-lkml-1-news-lb-839eef9f3a4cef4e.elb.us-west-2.amazonaws.com:119/nntp/readonly}#news.com.zx2c4.lists.wireguard) called ===
IMAP 10:10:07 1/16 mm_notify babble: {korg-lkml-1-news-lb-839eef9f3a4cef4e.elb.us-west-2.amazonaws.com:119/nntp/readonly}#news.com.zx2c4.lists.wireguard: [UNSEEN] 1 is first unseen message in com.zx2c4.lists.wireguard
IMAP DEBUG 10:10:07 1/16: STAT
IMAP DEBUG 10:10:07 1/16: 223 1 <CAHmME9oTZJhn4FZZo6uRK3XVKej3r8Je1GOhg4gALnujA7se4A@mail.gmail.com> article retrieved - request text separately
Opened folder "{korg-lkml-1-news-lb-839eef9f3a4cef4e.elb.us-west-2.amazonaws.com:119/nntp/readonly}#news.com.zx2c4.lists.wireguard" with 2000 messages
IMAP DEBUG 10:10:07 1/16: STAT
IMAP DEBUG 10:10:07 1/16: 223 1 <CAHmME9oTZJhn4FZZo6uRK3XVKej3r8Je1GOhg4gALnujA7se4A@mail.gmail.com> article retrieved - request text separately
Sorting by Arrival
IMAP DEBUG 10:10:07.8086: STAT
IMAP DEBUG 10:10:07 1/16: 223 1 <CAHmME9oTZJhn4FZZo6uRK3XVKej3r8Je1GOhg4gALnujA7se4A@mail.gmail.com> article retrieved - request text separately
First_sorted_flagged returning winner = 1


 ---- MAIL INDEX ----


 ---- INDEX MANAGER ----
IMAP DEBUG 10:10:07 1/16: XOVER 1776-1836
IMAP DEBUG 10:10:07 1/16: 224 Overview information follows for 1776 to 1836

 - process_cmd(cmd=505) -


  -----  MAIL VIEW  -----
IMAP DEBUG 10:10:11 1/16: HEAD 1776
IMAP DEBUG 10:10:11 1/16: 221 1776 <f96dc5cc-8952-62db-acf7-d8f66e9995c2@systemli.org> article retrieved - head follows

   ** NOTE by me: STALLED HERE FOR EVER..... >_< **
** Received SIGTERM **



fast_clean_up()
- completely_done_with_adrbks -
IMAP DEBUG 10:10:21 1/16: 0000000f LOGOUT
IMAP DEBUG 10:10:21 1/16: * BYE LOGOUT received
IMAP 10:10:21 1/16 mm_notify bye: {mail.messagingengine.com:993/imap/notls/ssl/user="scateu@fastmail.com"}INBOX: LOGOUT received
IMAP DEBUG 10:10:21 1/16: 0000000f OK Completed
IMAP DEBUG 10:10:21 1/16: QUIT
IMAP DEBUG 10:10:21 1/16: 205 closing connection - goodbye!
done with fast_clean_up

[PATCH] nntp: header responses use CRLF consistently

[Eric Wong]

Thanks, I'm pretty sure the following will fix it.

Not sure why others hadn't noticed since there's a lot of Alpine
users judging from Message-IDs.  Anyways I managed to replicate it
quickly with alpine in Debian ("alpine -url news://...") and
strace quickly showed me the difference.

Deploying to news.public-inbox.org shortly.
Cc-ing Konstantin for kernel.org.

---------------8<-----------------
Subject: [PATCH] nntp: header responses use CRLF consistently

Alpine is apparently stricter than other clients I've tried
w.r.t. using CRLF for headers.  So do the same thing we do for
bodies to ensure we only emit CRLFs and no bare LFs.

Reported-by: Wang Kang <i@scateu.me>
  https://public-inbox.org/meta/alpine.DEB.2.21.99.1901161043430.29788@la.scateu.me/
---
 lib/PublicInbox/NNTP.pm | 1 +
 1 file changed, 1 insertion(+)

diff --git a/lib/PublicInbox/NNTP.pm b/lib/PublicInbox/NNTP.pm
index 623ffd3..63d5870 100644
--- a/lib/PublicInbox/NNTP.pm
+++ b/lib/PublicInbox/NNTP.pm
@@ -515,6 +515,7 @@ sub set_art {
 sub _header ($) {
 	my $hdr = $_[0]->header_obj->as_string;
 	utf8::encode($hdr);
+	$hdr =~ s/(?<!\r)\n/\r\n/sg;
 	$hdr
 }
 
-- 
EW

Re: [Alpine-info] NNTP served by public-inbox stalled in Alpine 2.21.99

[Wang Kang]

Dear lists,

Great news! 

It has been just fixed by public-inbox.org. [1] 

And according to [1], lore.kernel.org will be deployed with the patched 
version soon.

Thank you so much.

[1]: https://public-inbox.org/meta/20190116045802.ikm67b4cwigso3tc@dcvr/

-- 
Wang Kang

On Wed, 16 Jan 2019, Wang Kang wrote:

> Dear lists,
> 
> I was trying to read NNTP news served by public-inbox [1], for example 
> [2] provided by Linux Kernel.
> 
> The index screen works fine. I can see the complete list of message titles 
> on the index screen. However, when I press enter on any of the message to 
> read the body of this news, the screen stucks for ever.
> 
> On the contrary, NNTP served by gmane, for example [3], works fine on 
> alpine.
> 
> I have attached those two debug logs generated by `alpine -d 4`. Hope you 
> can help solve this problem.
> 
> 
> By the way, I can read [2] from w3m correctly:
> 
>     w3m nntp://nntp.lore.kernel.org/com.zx2c4.lists.wireguard
> 
> 
> [1]: https://www.kernel.org/lore.html
> [2]: nntp://nntp.lore.kernel.org/com.zx2c4.lists.wireguard
> [3]: gmane.mail.public-inbox.general
> 
> 
> Thank you.
> 
> 

Re: [PATCH] nntp: header responses use CRLF consistently

[Konstantin Ryabitsev]

On Wed, Jan 16, 2019 at 04:58:02AM +0000, Eric Wong wrote:
> Thanks, I'm pretty sure the following will fix it.
> 
> Not sure why others hadn't noticed since there's a lot of Alpine
> users judging from Message-IDs.  Anyways I managed to replicate it
> quickly with alpine in Debian ("alpine -url news://...") and
> strace quickly showed me the difference.
> 
> Deploying to news.public-inbox.org shortly.
> Cc-ing Konstantin for kernel.org.

The latest master now runs on lore.kernel.org, so this problem should be
fixed there as well.

Best,
-K

Re: [PATCH] nntp: header responses use CRLF consistently

[Wang Kang]

Dear Konstantin,

The problem still exists. (Maybe a Perl 'restart' needed?)

You can test it with:

   alpine -url news://nntp.lore.kernel.org/org.kernel.vger.linux-btrfs

The already fixed one:

   alpine -url news://news.public-inbox.org/inbox.comp.mail.public-inbox.meta

Remember to press enter on one of the message to see the content, that's 
when it will stall.


Thank you.

-- 
Wang Kang

On Fri, 18 Jan 2019, Konstantin Ryabitsev wrote:

> On Wed, Jan 16, 2019 at 04:58:02AM +0000, Eric Wong wrote:
> > Thanks, I'm pretty sure the following will fix it.
> > 
> > Not sure why others hadn't noticed since there's a lot of Alpine
> > users judging from Message-IDs.  Anyways I managed to replicate it
> > quickly with alpine in Debian ("alpine -url news://...") and
> > strace quickly showed me the difference.
> > 
> > Deploying to news.public-inbox.org shortly.
> > Cc-ing Konstantin for kernel.org.
> 
> The latest master now runs on lore.kernel.org, so this problem should be
> fixed there as well.
> 
> Best,
> -K
> 

Re: [PATCH] nntp: header responses use CRLF consistently

[Konstantin Ryabitsev]

On Sat, Jan 19, 2019 at 09:14:15AM +0800, Wang Kang wrote:
> Dear Konstantin,
> 
> The problem still exists. (Maybe a Perl 'restart' needed?)

It was a bit weirder than that, but I got it sorted out. Try it now.

-K

Re: [PATCH] nntp: header responses use CRLF consistently

[Wang Kang]

It works!

Love you guys!

-- 
Wang Kang

On Fri, 18 Jan 2019, Konstantin Ryabitsev wrote:

> On Sat, Jan 19, 2019 at 09:14:15AM +0800, Wang Kang wrote:
> > Dear Konstantin,
> > 
> > The problem still exists. (Maybe a Perl 'restart' needed?)
> 
> It was a bit weirder than that, but I got it sorted out. Try it now.
> 
> -K
> 
>