Topic: Thunderbird e Win7 x64 [causa: F-Secure Client Security]

[aarnmunro1]

Buon giorno a tutti, il mio problema ha questi parametri:
S.O.   Windows 7 x 64 in italiano con tutti gli aggiornamenti
Thunderbird ultima release 3.1 ma anche le due precedenti 3.04. e 3.05
Account IMAP su server IMAIL interno (rete locale)
Dopo un tempo variabile da pc a pc ( attualmente 7 installazioni) viene notificato il timeout del server e da quel punto è assolutamente necessario riavviare la macchina per tornare a ricevere o trasmettere.
Il tempo può essere da pochi minuti a 3/4 ore casualmente.
Premetto che nella stessa rete ho client XP PRO e VISTA che non denunciano alcun problema.
Sui Pc incriminati ho già provato a disabilitare sia il servizio QOS che il driver per ricerca topologica sulla scheda di rete con il solo risultato di allungare (ma solo in alcuni casi!) l'arrivo del messaggio di timeout.
La completa mancanza di "senso" mi lascia perplesso e non so proprio dove agire...
saluti

[lucasali]

dopo l'errore di timeout hai problemi solo con tb o anche con altri programmi?
il messaggio di timeout lo da tb o il so?

[aarnmunro1]

Il messaggio di timeout è generato e riguarda solo Thunderbird. Gli altri applicativi, classici office, autocad ecc.. funzionano regolarmente.
Saluti

[rileonar]

Anch'io ho lo stesso identico problema.
Thunderbird di qualunque versione da 2.0.0.24 a 3.1.0 se utilizzato su Windows 7 Pro x64 con IMAP4 va in timeout dopo un tempo variabile da qualche minuto a qualche ora.
Quando scatta il timeout non c'è altra possibilità che riavviare Windows per ripristinare il normale funzionamento, ma solo fino al blocco successivo.
Ho provveduto a sniffare la rete lato client con Wireshark, e questo è il risultato:

Situazione "regolare" (Thunderbird funziona):

487   31.340658   <client ip>    <server ip>   TCP   49360 > imap [SYN] Seq=0 Win=8192 Len=0 MSS=1460 WS=2 SACK_PERM=1
488   31.341645   <server ip>   <client ip>    TCP   imap > 49360 [SYN, ACK] Seq=0 Ack=1 Win=5840 Len=0 MSS=1460 SACK_PERM=1 WS=7
489   31.341727   <client ip>    <server ip>   TCP   49360 > imap [ACK] Seq=1 Ack=1 Win=65700 Len=0
490   31.351224   <server ip>   <client ip>    IMAP   Response: * OK [CAPABILITY IMAP4REV1 LITERAL+ SASL-IR LOGIN-REFERRALS STARTTLS] mail.xyz.it IMAP4rev1 2007.398 at Tue, 3 May 2011 10:52:37 +0200 (CEST)
494   31.554573   <client ip>    <server ip>   TCP   49360 > imap [ACK] Seq=1 Ack=146 Win=65552 Len=0
498   31.873165   <client ip>    <server ip>   IMAP   Request: 2 login "<user>" "<password>"

da qui il dialogo prosegue in maniera regolare (tutte le connessioni IMAP vengono aperte regolarmente)

Situazione "bloccata" (Thunderbird NON funziona):

69   4.261197   <client ip>    <server ip>   TCP   49497 > imap [SYN] Seq=0 Win=8192 Len=0 MSS=1460 WS=2 SACK_PERM=1
72   4.262858   <server ip>   <client ip>    TCP   imap > 49497 [SYN, ACK] Seq=0 Ack=1 Win=5840 Len=0 MSS=1460 SACK_PERM=1 WS=7
73   4.262909   <client ip>    <server ip>   TCP   49497 > imap [ACK] Seq=1 Ack=1 Win=65700 Len=0
81   4.275920   <server ip>   <client ip>    IMAP   Response: * OK [CAPABILITY IMAP4REV1 LITERAL+ SASL-IR LOGIN-REFERRALS STARTTLS] mail.xyz.it IMAP4rev1 2007.398 at Tue, 3 May 2011 10:15:29 +0200 (CEST)
112   4.475410   <client ip>    <server ip>   TCP   49497 > imap [ACK] Seq=1 Ack=146 Win=65552 Len=0

.....  (trascorre il tempo impostato per il timeout delle sessioni verso il server)

1258   92.190476   <server ip>   <client ip>    IMAP   Response: * BYE Autologout (idle for too long)

Da qui si vede che in condizioni di blocco Thunderbird NON invia la richiesta "IMAP   Request: 2 login" al server, il quale attende e poi chiude per timeout. La stessa situazione è confermata dai logs lato mailserver.

Resta da capire il punto fondamentale, e cioè se sia Windows a bloccare in qualche modo la comunicazione o se sia Thunderbird che inspiegabilmente smette di comunicare via IMAP in maniera corretta.

Se questa discussione è ferma da troppo tempo posso aprirne una nuova, se necessario...

Grazie in anticipo per qualsiasi aiuto o suggerimento.

[croma.to]

Potresti attivare contemporaneamente il log su tb (http://forum.mozillaitalia.org/index.php?topic=29112.0) per capire se il pacchetto non viene bloccato nel mezzo (per esempio dall'antivirus)

croma.to

[rileonar]

Fatto. Ecco il log in situazione di fault:

7784[6b895c0]: ImapThreadMainLoop entering [this=79eb800]
0[a26140]: 79eb800:mail.xyz.it:NA:SetupWithUrl: clearing IMAP_CONNECTION_IS_OPEN
7784[6b895c0]: 79eb800:mail.xyz.it:NA:ProcessCurrentURL: entering
7784[6b895c0]: 79eb800:mail.xyz.it:NA:ProcessCurrentURL:imap://s%2Euser@mail.xyz.it:143/select%3E/Drafts:  = currentUrl
7544[6b8aec0]: ImapThreadMainLoop entering [this=959d000]
0[a26140]: 959d000:mail.xyz.it:NA:SetupWithUrl: clearing IMAP_CONNECTION_IS_OPEN
7544[6b8aec0]: 959d000:mail.xyz.it:NA:ProcessCurrentURL: entering
7544[6b8aec0]: 959d000:mail.xyz.it:NA:ProcessCurrentURL:imap://s%2Euser@mail.xyz.it:143/select%3E/INBOX:  = currentUrl
7784[6b895c0]: ReadNextLine [stream=7bfb748 nb=0 needmore=1]
7544[6b8aec0]: ReadNextLine [stream=9dd87a8 nb=0 needmore=1]
7784[6b895c0]: 79eb800:mail.xyz.it:NA:CreateNewLineFromSocket: clearing IMAP_CONNECTION_IS_OPEN - rv = 804b000e
7544[6b8aec0]: 959d000:mail.xyz.it:NA:CreateNewLineFromSocket: clearing IMAP_CONNECTION_IS_OPEN - rv = 804b000e
7784[6b895c0]: 79eb800:mail.xyz.it:NA:TellThreadToDie: close socket connection
7784[6b895c0]: 79eb800:mail.xyz.it:NA:CreateNewLineFromSocket: (null)
7544[6b8aec0]: 959d000:mail.xyz.it:NA:TellThreadToDie: close socket connection
7544[6b8aec0]: 959d000:mail.xyz.it:NA:CreateNewLineFromSocket: (null)
7784[6b895c0]: 79eb800:mail.xyz.it:NA:ProcessCurrentURL: aborting queued urls
7544[6b8aec0]: 959d000:mail.xyz.it:NA:ProcessCurrentURL: aborting queued urls
7784[6b895c0]: ImapThreadMainLoop leaving [this=79eb800]
7544[6b8aec0]: ImapThreadMainLoop leaving [this=959d000]


Contemporaneamente ecco ciò che compare nel log del mailserver:

May  3 15:47:10 mail imapd[21358]: imap service init from <client ip>
May  3 15:47:10 mail imapd[21359]: imap service init from <client ip>
May  3 15:50:10 mail imapd[21358]: Autologout user=??? host=[<client ip>]
May  3 15:50:10 mail imapd[21359]: Autologout user=??? host=[<client ip>]

Grazie di nuovo per l'aiuto.

[croma.to]

sarebbe più utile il log di TB insieme a quello di wireshark

sembrerebbe che
1) TB prova ad aprire la connesione

7544[6b8aec0]: 959d000:mail.xyz.it:NA:ProcessCurrentURL:imap://s%2Euser@mail.xyz.it:143/select%3E/INBOX:  = currentUrl

2) il server gli risponde

81   4.275920   <server ip>   <client ip>    IMAP   Response: * OK [CAPABILITY IMAP4REV1 LITERAL+ SASL-IR LOGIN-REFERRALS STARTTLS] mail.xyz.it IMAP4rev1 2007.398 at Tue, 3 May 2011 10:15:29 +0200 (CEST)

3) la risposta non arriva a TB che attende dati e poi chiude la connessione

7784[6b895c0]: ReadNextLine [stream=7bfb748 nb=0 needmore=1]
7544[6b8aec0]: ReadNextLine [stream=9dd87a8 nb=0 needmore=1]
7784[6b895c0]: 79eb800:mail.xyz.it:NA:CreateNewLineFromSocket: clearing IMAP_CONNECTION_IS_OPEN - rv = 804b000e
7544[6b8aec0]: 959d000:mail.xyz.it:NA:CreateNewLineFromSocket: clearing IMAP_CONNECTION_IS_OPEN - rv = 804b000e

come dicevo all'inizio, questa analisi potrebbe essere errata visto che i due log (TB e Wireshark) sono relativi a due momenti differenti

croma.to

[rileonar]

Giusta osservazione.

Quindi ho provveduto a rieseguire entrambe le prove (caso OK e caso FAULT) dove i log stavolta sono consistenti, cioè presi contemporaneamente lato Thunderbird, Wireshark e mailserver:


Caso OK
======

Log Thunderbird:
5420[8d84480]: ImapThreadMainLoop entering [this=7b02800]
0[2b26140]: 7b02800:mail.<xyz>.it:NA:SetupWithUrl: clearing IMAP_CONNECTION_IS_OPEN
5420[8d84480]: 7b02800:mail.<xyz>.it:NA:ProcessCurrentURL: entering
5420[8d84480]: 7b02800:mail.<xyz>.it:NA:ProcessCurrentURL:imap://<user>@mail.<xyz>.it:143/select%3E/INBOX:  = currentUrl
5420[8d84480]: ReadNextLine [stream=7cf29c8 nb=119 needmore=0]
5420[8d84480]: 7b02800:mail.<xyz>.it:NA:CreateNewLineFromSocket: * OK [CAPABILITY IMAP4REV1 LOGIN-REFERRALS] mail.<xyz>.it IMAP4rev1 2007.398 at Tue, 3 May 2011 17:19:16 +0200 (CEST)


Log Wireshark:
714   69.217792   <client ip>   <server ip>   TCP   49269 > imap [SYN] Seq=0 Win=8192 Len=0 MSS=1460 WS=2 SACK_PERM=1
715   69.218555   <server ip>   <client ip>   TCP   imap > 49269 [SYN, ACK] Seq=0 Ack=1 Win=5840 Len=0 MSS=1460 SACK_PERM=1 WS=7
716   69.218602   <client ip>   <server ip>   TCP   49269 > imap [ACK] Seq=1 Ack=1 Win=65700 Len=0
717   69.226952   <server ip>   <client ip>   IMAP   Response: * OK [CAPABILITY IMAP4REV1 LITERAL+ SASL-IR LOGIN-REFERRALS STARTTLS] mail.<xyz>.it IMAP4rev1 2007.398 at Tue, 3 May 2011 17:19:16 +0200 (CEST)
723   69.430108   <client ip>   <server ip>   TCP   49269 > imap [ACK] Seq=1 Ack=146 Win=65552 Len=0
727   69.460180   <client ip>   <server ip>   IMAP   Request: 2 login "<user>" "<password>"

Log mailserver:
May  3 17:19:16 mail imapd[25896]: imap service init from <client ip>
May  3 17:19:17 mail imapd[25896]: Login user=<user> host=[<client ip>]
May  3 17:19:22 mail imapd[25899]: imap service init from <client ip>
May  3 17:19:23 mail imapd[25899]: Login user=<user> host=[<client ip>]
May  3 17:19:24 mail imapd[25902]: imap service init from <client ip>
May  3 17:19:24 mail imapd[25902]: Login user=<user> host=[<client ip>]
May  3 17:19:26 mail imapd[25905]: imap service init from <client ip>
May  3 17:19:27 mail imapd[25905]: Login user=<user> host=[<client ip>]
May  3 17:19:29 mail imapd[25907]: imap service init from <client ip>
May  3 17:19:30 mail imapd[25907]: Login user=<user> host=[<client ip>]
May  3 17:19:56 mail imapd[25931]: imap service init from <client ip>
May  3 17:19:57 mail imapd[25931]: Login user=<user> host=[<client ip>]
May  3 17:20:00 mail imapd[25933]: imap service init from <client ip>
May  3 17:20:01 mail imapd[25933]: Login user=<user> host=[<client ip>]



Caso FAULT
========

Log Thunderbird:
1028[7d84480]: ImapThreadMainLoop entering [this=7429800]
0[2b26140]: 7429800:mail.<xyz>.it:NA:SetupWithUrl: clearing IMAP_CONNECTION_IS_OPEN
1028[7d84480]: 7429800:mail.<xyz>.it:NA:ProcessCurrentURL: entering
1028[7d84480]: 7429800:mail.<xyz>.it:NA:ProcessCurrentURL:imap://<user>@mail.<xyz>.it:143/select%3E/INBOX:  = currentUrl
1028[7d84480]: ReadNextLine [stream=7ff29c8 nb=0 needmore=1]
1028[7d84480]: 7429800:mail.<xyz>.it:NA:CreateNewLineFromSocket: clearing IMAP_CONNECTION_IS_OPEN - rv = 804b000e
1028[7d84480]: 7429800:mail.<xyz>.it:NA:TellThreadToDie: close socket connection
1028[7d84480]: 7429800:mail.<xyz>.it:NA:CreateNewLineFromSocket: (null)
1028[7d84480]: 7429800:mail.<xyz>.it:NA:ProcessCurrentURL: aborting queued urls
1028[7d84480]: ImapThreadMainLoop leaving [this=7429800]

Log Wireshark:
628   33.510538   <client ip>   <server ip>   TCP   49350 > imap [SYN] Seq=0 Win=8192 Len=0 MSS=1460 WS=2 SACK_PERM=1
662   36.506614   <client ip>   <server ip>   TCP   49350 > imap [SYN] Seq=0 Win=8192 Len=0 MSS=1460 WS=2 SACK_PERM=1
663   36.507455   <server ip>   <client ip>   TCP   imap > 49350 [SYN, ACK] Seq=0 Ack=1 Win=5840 Len=0 MSS=1460 SACK_PERM=1 WS=7
664   36.507593   <client ip>   <server ip>   TCP   49350 > imap [ACK] Seq=1 Ack=1 Win=65700 Len=0
665   36.516992   <server ip>   <client ip>   IMAP   Response: * OK [CAPABILITY IMAP4REV1 LITERAL+ SASL-IR LOGIN-REFERRALS STARTTLS] mail.<xyz>.it IMAP4rev1 2007.398 at Tue, 3 May 2011 18:09:22 +0200 (CEST)
676   36.725047   <client ip>   <server ip>   TCP   49350 > imap [ACK] Seq=1 Ack=146 Win=65552 Len=0
729   40.642114   <server ip>   <client ip>   TCP   imap > 49342 [FIN, ACK] Seq=1 Ack=1 Win=46 Len=0
731   40.843205   <client ip>   <server ip>   TCP   49342 > imap [ACK] Seq=1 Ack=1 Win=16379 Len=0

Log mailserver:
May  3 18:09:22 mail imapd[28329]: imap service init from <client ip>
May  3 18:12:22 mail imapd[28329]: Autologout user=??? host=[<client ip>]

[croma.to]

come puoi notare, nel caso ok, il messaggio di benvenuto, visibile in wireshark, compare nel log di tb; nel secondo caso no (in questo caso hai messaggi di errore nella "console degli errori" di TB ?) .

secondo me, dovresti controllare antivirus e antispam

croma.to

[rileonar]

Non ho errori corrispondenti all'istante temporale in cui secondo me si verifica il problema, ma solo quando la connessione va in timeout: a quel punto compare il popup di Thunderbird in cui lamenta la disconnessione per timeout.

Il problema non è causato da antivirus o antispam, perché anche disabilitandoli il problema rimane, e lo stesso antivirus su altre macchine non Win 7 non ostacola la comunicazione. Infine se fosse un problema di antivirus o di altre applicazioni tipo Windows Firewall (peraltro completamente disabilitato) si verificherebbe sempre, invece al primo run di Thunderbird dopo il riavvio di Windows non si verifica, funziona sempre.

Potrei sbagliare ma secondo me il problema si crea in Thunderbird quando per qualche motivo crede che ci siano delle connessioni IMAP precedentemente aperte e si incarta cercando di chiuderle:

723   69.430108   <client ip>   <server ip>   TCP.....

e subito dopo:

727   69.460180   <client ip>   <server ip>   IMAP

Mentre invece dopo un po' che sta girando:

676   36.725047   <client ip>   <server ip>   TCP

poi più niente, non prova neanche a mandare subito fuori la richiesta IMAP di login; la situazione rimane congelata così finché il server non si stufa e chiude la sessione:

729   40.642114   <server ip>   <client ip>   TCP

(nota il timestamp molto più elevato...)

[croma.to]

in entrambi i casi, TB apre una nuova connessione (il pacchetto TCP SYN). nel caso KO, il contenuto del pacchetto 665 non arriva a TB che resta bloccato su ReadNextLine [stream=7ff29c8 nb=0 needmore=1] (cioè in attesa di dati dal server) fino a quando non scade il timeout. Secondo il protocollo IMAP, è questo che scatena la richiesta di login da parte del client (TB)

coma.to

[klades]

Fai una prova mettendo in Thunderbird la preferenza mail.imap.max_cached_connections al valore 1 (se non cambia niente, riportala al valore di default).

[rileonar]

@klades: ho provato a portare il valore di mail.imap.max_cached_connections da 10 a 1, ma non è cambiato nulla.


@croma.to: il pacchetto che non arriva a Thunderbird è correttamente inviato dal server IMAP e sniffato da wireshark (il pacchetto n. 665 del log wireshark FAULT). Quindi se Thunderbird non lo riceve:

1) lo scarta Windows o un'altra applicazione tipo antivirus dopo che è passato attraverso lo stack TCP/IP e wireshark

2) lo scarta Thunderbird in un qualche suo stack interno prima che arrivi al suo "logger" interno



Scoprendo quale delle due è quella giusta ci porterebbe molto vicini alla soluzione, ma non ho elementi per risolvere il problema. La cosa veramente inspiegabile è che la prima volta che Thunderbird parte il pacchetto lo riceve, mentre dopo un po' non lo riceve più e l'unico modo per resettarlo è riavviare tutto.



Grazie ancora per il supporto!

[croma.to]

UW!

al posto di riavviare il computer, prova a vedere cosa succede disabilitando e poi riabilitando la rete

croma.to

[rileonar]

Ho provato a disabilitare/riabilitare, stacca&attacca il cavo ed anche attendere che vada in suspend mode e poi ripristinarlo: nessuna differenza, Thunderbird non riparte mai.

Ho provato anche con la versione a 64 bits (lanikai 3.1.9) più per curiosità che per altro: sempre stesso problema.