how to debug

how to debug

[lee]

Hi,

with emacs 24 from tonight, gnus sometimes keeps emacs busy indefinitely
when checking for new news (pressing `g' in the group buffer).  I'm
getting messages like:

,---- [ *Messages* ]
| Checking new news...
| Reading active file from diary via nndiary...
| Opening nndiary server on diary...done
| Reading incoming mail from file...
| nndiary: Reading incoming mail (no new mail)...done
| Reading active file from diary via nndiary...done
| gnutls.c: [0] (Emacs) fatal error: A TLS packet with unexpected length was received.
| Reading active file from yun via nnml...
| Reading incoming mail from file... [2 times]
| Reading incoming mail from maildir...
| Wrote /home/lee/Mail/mail/lists/mythtv-users/9043
| Wrote /home/lee/Mail/mail/lists/mythtv-users/9044
| Wrote /home/lee/Mail/mail/lists/debian-user/96166
| [...]
| Wrote /home/lee/Mail/mail/lists/debian-user/96168
| nnml: Reading incoming mail (21 new)...done
| Reading active file from yun via nnml...done
| Quit
`----

When I press Ctrl-g, emacs isn't busy anymore.  I can even check for
news again, and it eventually works fine.

Is there a way to find out what gnus or emacs are doing when emacs is
busy?  I've already "(setq debug-on-error t)" in ~/.emacs.  A bug
report like this probably isn't useful at all, so it would be nice if I
could provide some more information.

As to the TLS error: I'm not aware of using TLS.  I have an ~/.authinfo
file for one of the news servers, though.

Re: how to debug

[Tassilo Horn]

lee <lee@yun.yagibdah.de> writes:

Hi!

> with emacs 24 from tonight, gnus sometimes keeps emacs busy
> indefinitely when checking for new news (pressing `g' in the group
> buffer).  I'm getting messages like:
>
> ,---- [ *Messages* ]
> | Checking new news...
> | Reading active file from diary via nndiary...
> | Opening nndiary server on diary...done
> | Reading incoming mail from file...
> | nndiary: Reading incoming mail (no new mail)...done
> | Reading active file from diary via nndiary...done
> | gnutls.c: [0] (Emacs) fatal error: A TLS packet with unexpected length was received.

I get that error twice a day, too.  But it doesn't seem to have any bad
effect...

> | Reading active file from yun via nnml...
> | Reading incoming mail from file... [2 times]
> | Reading incoming mail from maildir...
> | Wrote /home/lee/Mail/mail/lists/mythtv-users/9043
> | Wrote /home/lee/Mail/mail/lists/mythtv-users/9044
> | Wrote /home/lee/Mail/mail/lists/debian-user/96166
> | [...]
> | Wrote /home/lee/Mail/mail/lists/debian-user/96168
> | nnml: Reading incoming mail (21 new)...done
> | Reading active file from yun via nnml...done
> | Quit
> `----
>
> When I press Ctrl-g, emacs isn't busy anymore.  I can even check for
> news again, and it eventually works fine.

I can observe a similar behavior since month.  Usually, the last output
is "nnimap read 78k" and then it stalls until I hit C-g.  After that,
all works fine again.

> Is there a way to find out what gnus or emacs are doing when emacs is
> busy?  I've already "(setq debug-on-error t)" in ~/.emacs.  A bug
> report like this probably isn't useful at all, so it would be nice if
> I could provide some more information.

Set debug-on-quit instead.  Then you are put into the debugger on C-g
and you can figure out what function was executing when the freeze
occured.

> As to the TLS error: I'm not aware of using TLS.  I have an ~/.authinfo
> file for one of the news servers, though.

I think Gnus uses TLS by default if the server supports it.

Bye,
Tassilo
-- 
Sent from my Emacs

Re: how to debug

[Leonidas Tsampros]

Tassilo Horn <tassilo@member.fsf.org> writes:
> lee <lee@yun.yagibdah.de> writes:
>
> Hi!
>
>> with emacs 24 from tonight, gnus sometimes keeps emacs busy
>> indefinitely when checking for new news (pressing `g' in the group
>> buffer).  I'm getting messages like:
>>
>> ,---- [ *Messages* ]
>> | Checking new news...
>> | Reading active file from diary via nndiary...
>> | Opening nndiary server on diary...done
>> | Reading incoming mail from file...
>> | nndiary: Reading incoming mail (no new mail)...done
>> | Reading active file from diary via nndiary...done
>> | gnutls.c: [0] (Emacs) fatal error: A TLS packet with unexpected length was received.
>
> I get that error twice a day, too.  But it doesn't seem to have any bad
> effect...
>
>> | Reading active file from yun via nnml...
>> | Reading incoming mail from file... [2 times]
>> | Reading incoming mail from maildir...
>> | Wrote /home/lee/Mail/mail/lists/mythtv-users/9043
>> | Wrote /home/lee/Mail/mail/lists/mythtv-users/9044
>> | Wrote /home/lee/Mail/mail/lists/debian-user/96166
>> | [...]
>> | Wrote /home/lee/Mail/mail/lists/debian-user/96168
>> | nnml: Reading incoming mail (21 new)...done
>> | Reading active file from yun via nnml...done
>> | Quit
>> `----
>>
>> When I press Ctrl-g, emacs isn't busy anymore.  I can even check for
>> news again, and it eventually works fine.
>
> I can observe a similar behavior since month.  Usually, the last output
> is "nnimap read 78k" and then it stalls until I hit C-g.  After that,
> all works fine again.

I can confirm this too! Using yesterday's emacs 24, and a pop3 mail
source I can confirm the exact same behaviour. It randomly stays stuck
while reading mail from the pop3 server. Pressing C-g and g to get the
news again eventually works fine with no bad side effects.

Setting debug-on-quit to t, I caught this but it's probably not enough:

Debugger entered--Lisp error: (quit)
  pop3-accept-process-output(#<process POP>)
  pop3-wait-for-messages(#<process POP> 22 175976)
  pop3-send-streaming-command(#<process POP> "RETR" 22 175976)
  pop3-movemail("~/.emacs-mail-crash-box")
mail-source-fetch-pop((pop :server "mail.popserver.com" :user "ltsampros" :password "password") #[(file orig-file) "\303\b\304\305	\206\b\n\232?\205\306\n\307\"\310%\207" [file in-group orig-file nnmail-split-incoming nnml-save-mail nil nnmail-get-split-group (pop :server "mail.popserver.com" :user "ltsampros" :password "password") nnml-active-number] 7])
  mail-source-fetch((pop :server "mail.popserver.com" :user "ltsampros" :password "password") #[(file orig-file) "\303\b\304\305	\206\b\n\232?\205\306\n\307\"\310%\207" [file in-group orig-file nnmail-split-incoming nnml-save-mail nil nnmail-get-split-group (pop :server "mail.popserver.com" :user "ltsampros" :password "password") nnml-active-number] 7])
  nnmail-get-new-mail-1(nnml nnml-save-incremental-nov "~/Mail.Gnus" nil nil nil)
  nnmail-get-new-mail(nnml nnml-save-incremental-nov "~/Mail.Gnus" nil)
  nnml-request-scan(nil "")
  gnus-request-scan(nil (nnml ""))
  gnus-read-active-file-1((nnml "") nil)
  gnus-read-active-for-groups((nnml "") (many-many-many data here)
  gnus-get-unread-articles(nil)
  gnus-setup-news(nil nil nil)
  byte-code("\b\204	\204\306 \210\202L\307\310!\210\311\n!\f\204\203!\312 \210\313\314\b#\210\307\315!\210\2036\316\317\320\"\210\321 \210\322!\210\323 \210\324\325!\210\326 \210\307\327!\210\314\207" [dont-connect did-connect gnus-startup-file gnus-current-startup-file gnus-slave gnus-use-dribble-file gnus-group-quit gnus-run-hooks gnus-startup-hook gnus-make-newsrc-file gnus-dribble-read-file gnus-setup-news nil gnus-setup-news-hook gnus-request-create-group "queue" (nndraft "") gnus-start-draft-setup gnus-group-list-groups gnus-group-first-unread-group gnus-configure-windows group gnus-group-set-mode-line gnus-started-hook level gnus-agent] 4)
  gnus-1(nil nil nil)
  gnus(nil)
  call-interactively(gnus t nil)
  execute-extended-command(nil)
  call-interactively(execute-extended-command nil nil)

Best Regards,
Leonidas Tsampros

[...]

Re: how to debug

[lee]

Leonidas Tsampros <ltsampros@upnet.gr> writes:

> Tassilo Horn <tassilo@member.fsf.org> writes:
>> lee <lee@yun.yagibdah.de> writes:
>
> [...]
>>> with emacs 24 from tonight, gnus sometimes keeps emacs busy
>>> indefinitely when checking for new news (pressing `g' in the group
>>> buffer).  I'm getting messages like:
>
> [...]
>>>
>>> When I press Ctrl-g, emacs isn't busy anymore.  I can even check for
>>> news again, and it eventually works fine.
>>
>> I can observe a similar behavior since month.  Usually, the last output
>> is "nnimap read 78k" and then it stalls until I hit C-g.  After that,
>> all works fine again.
>
> I can confirm this too! Using yesterday's emacs 24, and a pop3 mail
> source I can confirm the exact same behaviour. It randomly stays stuck
> while reading mail from the pop3 server. Pressing C-g and g to get the
> news again eventually works fine with no bad side effects.
>
> Setting debug-on-quit to t, I caught this but it's probably not enough:
>
> Debugger entered--Lisp error: (quit)
>   pop3-accept-process-output(#<process POP>)
>   pop3-wait-for-messages(#<process POP> 22 175976)
>   pop3-send-streaming-command(#<process POP> "RETR" 22 175976)
>   pop3-movemail("~/.emacs-mail-crash-box")
> mail-source-fetch-pop((pop :server "mail.popserver.com" :user
> "ltsampros" :password "password") #[(file orig-file) "\303\b\304\305
> [...]

Do you have any nntp servers in use?  It looks as if this problem comes
up when some sort of authentication is involved, as is with Tassilos
IMAP, your POP3 and one of my nntp servers.

Can just remove the nntp server from my select methods without any bad
effects to see if the problem is still there without it?

Re: how to debug

[Lars Magne Ingebrigtsen]

Leonidas Tsampros <ltsampros@upnet.gr> writes:

> Setting debug-on-quit to t, I caught this but it's probably not enough:
>
> Debugger entered--Lisp error: (quit)
>   pop3-accept-process-output(#<process POP>)
>   pop3-wait-for-messages(#<process POP> 22 175976)

What's in the pop3 buffer at this point?

And does setting `pop3-stream-length' to 1 make the problem go away?

-- 
(domestic pets only, the antidote for overdose, milk.)
  bloggy blog http://lars.ingebrigtsen.no/

Re: how to debug

[Leonidas Tsampros]

Lars Magne Ingebrigtsen <larsi@gnus.org> writes:
> Leonidas Tsampros <ltsampros@upnet.gr> writes:
>
>> Setting debug-on-quit to t, I caught this but it's probably not enough:
>>
>> Debugger entered--Lisp error: (quit)
>>   pop3-accept-process-output(#<process POP>)
>>   pop3-wait-for-messages(#<process POP> 22 175976)
>
> What's in the pop3 buffer at this point?
>
> And does setting `pop3-stream-length' to 1 make the problem go away?

Here it is in action. At exactly this point Gnus is in an infite loop
betweek pop3-wait-for-messages and pop3-number-of-responses:

  re-search-forward("^\\.?\n" nil t)
  pop3-number-of-responses(90992)
  pop3-wait-for-messages(#<process POP> 13 90992)
  pop3-send-streaming-command(#<process POP> "RETR" 13 90992)
  pop3-movemail("~/.emacs-mail-crash-box")
  mail-source-fetch-pop((pop :server "mail.popserver.com" :user "ltsampros" :password "password") #[(file orig-file) "\303\b\304\305	\206

Re: how to debug

[Lars Magne Ingebrigtsen]

Leonidas Tsampros <ltsampros@upnet.gr> writes:

>> And does setting `pop3-stream-length' to 1 make the problem go away?
>
> Here it is in action. At exactly this point Gnus is in an infite loop
> betweek pop3-wait-for-messages and pop3-number-of-responses:
>
>   re-search-forward("^\\.?\n" nil t)
>   pop3-number-of-responses(90992)
>   pop3-wait-for-messages(#<process POP> 13 90992)
>   pop3-send-streaming-command(#<process POP> "RETR" 13 90992)
>   pop3-movemail("~/.emacs-mail-crash-box")
>   mail-source-fetch-pop((pop :server "mail.popserver.com" :user
> "ltsampros" :password "password") #[(file orig-file) "\303\b\304\305
> \206

Your message was cut off here.

-- 
(domestic pets only, the antidote for overdose, milk.)
  bloggy blog http://lars.ingebrigtsen.no/

Re: how to debug

[Leonidas Tsampros]

Lars Magne Ingebrigtsen <larsi@gnus.org> writes:

> Leonidas Tsampros <ltsampros@upnet.gr> writes:
>
>>> And does setting `pop3-stream-length' to 1 make the problem go away?
>>
>> Here it is in action. At exactly this point Gnus is in an infite loop
>> betweek pop3-wait-for-messages and pop3-number-of-responses:
>>
>>   re-search-forward("^\\.?\n" nil t)
>>   pop3-number-of-responses(90992)
>>   pop3-wait-for-messages(#<process POP> 13 90992)
>>   pop3-send-streaming-command(#<process POP> "RETR" 13 90992)
>>   pop3-movemail("~/.emacs-mail-crash-box")
>>   mail-source-fetch-pop((pop :server "mail.popserver.com" :user
>> "ltsampros" :password "password") #[(file orig-file) "\303\b\304\305
>> \206
>
> Your message was cut off here.

Yeah. Gnus had warned me of non-printable characters. I chose to replace
non-printable characters with . Here is the continuation of the email:

  re-search-forward("^\\.?\n" nil t)
  pop3-number-of-responses(90992)
  pop3-wait-for-messages(#<process POP> 13 90992)
  pop3-send-streaming-command(#<process POP> "RETR" 13 90992)
  pop3-movemail("~/.emacs-mail-crash-box")
  mail-source-fetch-pop((pop :server "mail.popserver.com" :user
"ltsampros" :password "password") #[(file orig-file) "\303\b\304\305
\206.\b\n\232?\205.\306\n\307\"\310%\207" [file in-group orig-file
nnmail-split-incoming nnml-save-mail nil nnmail-get-split-group (pop
:server "mail.popserver.com" :user "ltsampros" :password "password")
nnml-active-number] 7])
  mail-source-fetch((pop :server "mail.popserver.com" :user "ltsampros"
:password "password") #[(file orig-file) "\303\b\304\305
\206.\b\n\232?\205.\306\n\307\"\310%\207" [file in-group orig-file
nnmail-split-incoming nnml-save-mail nil nnmail-get-split-group (pop
:server "mail.popserver.com" :user "ltsampros" :password "password")
nnml-active-number] 7])
  nnmail-get-new-mail-1(nnml nnml-save-incremental-nov "~/Mail.Gnus" nil nil nil)
  nnmail-get-new-mail(nnml nnml-save-incremental-nov "~/Mail.Gnus" nil)
  nnml-request-scan(nil "")
  gnus-request-scan(nil (nnml ""))
  gnus-read-active-file-1((nnml "") nil)
  gnus-read-active-for-groups((nnml "") ((very many big list of groups and ranges ))
  gnus-get-unread-articles(nil)
  gnus-group-get-new-news(nil)
  call-interactively(gnus-group-get-new-news nil nil)

The 5 last lines of the rather long "trace of POP session to
mail.popserver.com" are the following:

As for binary drivers...  They work ok *if* and *while* the company wants
to support the hardware/OS.  Onc-ERR Format restriction violation. Email Session ID: {4E272662-76-4818C96-FFFF}

Process POP connection broken by remote peer

I can post the whole buffer if you want in pastebin or a similar
service.

Many Thanks
Leonidas Tsampros

Re: how to debug

[Lars Magne Ingebrigtsen]

Leonidas Tsampros <ltsampros@upnet.gr> writes:

>>> Here it is in action. At exactly this point Gnus is in an infite loop
>>> betweek pop3-wait-for-messages and pop3-number-of-responses:

I've now added a check in that loop for this:

> to support the hardware/OS.  Onc-ERR Format restriction
> violation. Email Session ID: {4E272662-76-4818C96-FFFF}
>
> Process POP connection broken by remote peer

Which means that your pop3 server hung up the connection because of a
server-side parsing error.

-- 
(domestic pets only, the antidote for overdose, milk.)
  bloggy blog http://lars.ingebrigtsen.no/

Re: how to debug

[lee]

Tassilo Horn <tassilo@member.fsf.org> writes:

> lee <lee@yun.yagibdah.de> writes:
>
> Hi!
>
>> with emacs 24 from tonight, gnus sometimes keeps emacs busy
>> indefinitely when checking for new news (pressing `g' in the group
>> buffer).  I'm getting messages like:
>>
>
> [...]
>> | gnutls.c: [0] (Emacs) fatal error: A TLS packet with unexpected
>> | length was received.
>
> I get that error twice a day, too.  But it doesn't seem to have any bad
> effect...

Good to know that it doesn't seem to have bad effects :)

>> When I press Ctrl-g, emacs isn't busy anymore.  I can even check for
>> news again, and it eventually works fine.
>
> I can observe a similar behavior since month.  Usually, the last output
> is "nnimap read 78k" and then it stalls until I hit C-g.  After that,
> all works fine again.

Hm, a while ago someone posted here who had a problem with connections
to news servers, too.

>> Is there a way to find out what gnus or emacs are doing when emacs is
>> busy?
> [...]
>
> Set debug-on-quit instead.  Then you are put into the debugger on C-g
> and you can figure out what function was executing when the freeze
> occured.

Here's what I get:

,----
| Debugger entered--Lisp error: (quit)
|   signal(quit nil)
|   byte-code("\b\204\a.\301 \210\302\303\304\"\207" [debug-on-quit nntp-close-server signal quit nil] 3)
|   byte-code("\306\b	\n#\210\v\205.