32_mailcheck.pm - Prüfen, ob Verbindung besteht

[betateilchen]

Hallo Andre,

jede Nacht - fast immer zur gleichen Uhrzeit - in meinem Logfile:

Code Auswählen Erweitern


2018.04.11 01:41:47.618 1: PERL WARNING: Trying command when NOT connected! at /usr/share/perl5/Mail/IMAPClient.pm line 122.
Mail::IMAPClient::LastError(Mail::IMAPClient=HASH(0x6500ec0), "NO not connected") called at /usr/share/perl5/Mail/IMAPClient.pm line 1545
Mail::IMAPClient::_send_line(Mail::IMAPClient=HASH(0x6500ec0), "435 SELECT INBOX", 0) called at /usr/share/perl5/Mail/IMAPClient.pm line 1321
Mail::IMAPClient::_imap_command_do(Mail::IMAPClient=HASH(0x6500ec0), "SELECT INBOX") called at /usr/share/perl5/Mail/IMAPClient.pm line 1226
Mail::IMAPClient::_imap_command(Mail::IMAPClient=HASH(0x6500ec0), "SELECT INBOX") called at /usr/share/perl5/Mail/IMAPClient.pm line 846
Mail::IMAPClient::select(Mail::IMAPClient=HASH(0x6500ec0), "INBOX") called at ./FHEM/32_mailcheck.pm line 275
main::mailcheck_poll(HASH(0x2d98c18)) called at fhem.pl line 3108
main::HandleTimeout() called at fhem.pl line 636
2018.04.11 01:41:47.620 1: PERL WARNING: Trying command when NOT connected! LastError was: NO not connected at /usr/share/perl5/Mail/IMAPClient.pm line 122.
Mail::IMAPClient::LastError(Mail::IMAPClient=HASH(0x6500ec0), "Error sending '435 SELECT INBOX': NO not connected") called at /usr/share/perl5/Mail/IMAPClient.pm line 1322
Mail::IMAPClient::_imap_command_do(Mail::IMAPClient=HASH(0x6500ec0), "SELECT INBOX") called at /usr/share/perl5/Mail/IMAPClient.pm line 1226
Mail::IMAPClient::_imap_command(Mail::IMAPClient=HASH(0x6500ec0), "SELECT INBOX") called at /usr/share/perl5/Mail/IMAPClient.pm line 846
Mail::IMAPClient::select(Mail::IMAPClient=HASH(0x6500ec0), "INBOX") called at ./FHEM/32_mailcheck.pm line 275
main::mailcheck_poll(HASH(0x2d98c18)) called at fhem.pl line 3108
main::HandleTimeout() called at fhem.pl line 636
2018.04.11 01:41:47.622 1: PERL WARNING: Trying command when NOT connected! LastError was: Error sending '435 SELECT INBOX': NO not connected at /usr/share/perl5/Mail/IMAPClient.pm line 122.
Mail::IMAPClient::LastError(Mail::IMAPClient=HASH(0x6500ec0), "Error sending '435 SELECT INBOX': NO not connected") called at /usr/share/perl5/Mail/IMAPClient.pm line 1275
Mail::IMAPClient::_imap_command(Mail::IMAPClient=HASH(0x6500ec0), "SELECT INBOX") called at /usr/share/perl5/Mail/IMAPClient.pm line 846
Mail::IMAPClient::select(Mail::IMAPClient=HASH(0x6500ec0), "INBOX") called at ./FHEM/32_mailcheck.pm line 275
main::mailcheck_poll(HASH(0x2d98c18)) called at fhem.pl line 3108
main::HandleTimeout() called at fhem.pl line 636
2018.04.11 01:41:47.625 1: PERL WARNING: Trying command when NOT connected! at /usr/share/perl5/Mail/IMAPClient.pm line 122.
Mail::IMAPClient::LastError(Mail::IMAPClient=HASH(0x6500ec0), "NO not connected") called at /usr/share/perl5/Mail/IMAPClient.pm line 1545
Mail::IMAPClient::_send_line(Mail::IMAPClient=HASH(0x6500ec0), "436 IDLE", 0) called at /usr/share/perl5/Mail/IMAPClient.pm line 1321
Mail::IMAPClient::_imap_command_do(Mail::IMAPClient=HASH(0x6500ec0), "IDLE", "+") called at /usr/share/perl5/Mail/IMAPClient.pm line 1226
Mail::IMAPClient::_imap_command(Mail::IMAPClient=HASH(0x6500ec0), "IDLE", "+") called at /usr/share/perl5/Mail/IMAPClient.pm line 1119
Mail::IMAPClient::idle(Mail::IMAPClient=HASH(0x6500ec0)) called at ./FHEM/32_mailcheck.pm line 276
main::mailcheck_poll(HASH(0x2d98c18)) called at fhem.pl line 3108
main::HandleTimeout() called at fhem.pl line 636
2018.04.11 01:41:47.627 1: PERL WARNING: Trying command when NOT connected! LastError was: NO not connected at /usr/share/perl5/Mail/IMAPClient.pm line 122.
Mail::IMAPClient::LastError(Mail::IMAPClient=HASH(0x6500ec0), "Error sending '436 IDLE': NO not connected") called at /usr/share/perl5/Mail/IMAPClient.pm line 1322
Mail::IMAPClient::_imap_command_do(Mail::IMAPClient=HASH(0x6500ec0), "IDLE", "+") called at /usr/share/perl5/Mail/IMAPClient.pm line 1226
Mail::IMAPClient::_imap_command(Mail::IMAPClient=HASH(0x6500ec0), "IDLE", "+") called at /usr/share/perl5/Mail/IMAPClient.pm line 1119
Mail::IMAPClient::idle(Mail::IMAPClient=HASH(0x6500ec0)) called at ./FHEM/32_mailcheck.pm line 276
main::mailcheck_poll(HASH(0x2d98c18)) called at fhem.pl line 3108
main::HandleTimeout() called at fhem.pl line 636
2018.04.11 01:41:47.629 1: PERL WARNING: Trying command when NOT connected! LastError was: Error sending '436 IDLE': NO not connected at /usr/share/perl5/Mail/IMAPClient.pm line 122.
Mail::IMAPClient::LastError(Mail::IMAPClient=HASH(0x6500ec0), "Error sending '436 IDLE': NO not connected") called at /usr/share/perl5/Mail/IMAPClient.pm line 1275
Mail::IMAPClient::_imap_command(Mail::IMAPClient=HASH(0x6500ec0), "IDLE", "+") called at /usr/share/perl5/Mail/IMAPClient.pm line 1119
Mail::IMAPClient::idle(Mail::IMAPClient=HASH(0x6500ec0)) called at ./FHEM/32_mailcheck.pm line 276
main::mailcheck_poll(HASH(0x2d98c18)) called at fhem.pl line 3108
main::HandleTimeout() called at fhem.pl line 636
2018.04.11 01:41:47.632 1: PERL WARNING: Trying command when NOT connected! LastError was: Error sending '436 IDLE': NO not connected at /usr/share/perl5/Mail/IMAPClient.pm line 122.
Mail::IMAPClient::LastError(Mail::IMAPClient=HASH(0x6500ec0), "NO not connected") called at /usr/share/perl5/Mail/IMAPClient.pm line 1617
Mail::IMAPClient::_read_line(Mail::IMAPClient=HASH(0x6500ec0)) called at /usr/share/perl5/Mail/IMAPClient.pm line 1393
Mail::IMAPClient::_get_response(Mail::IMAPClient=HASH(0x6500ec0), "*", qr((?!BAD|BYE|NO)(?:\d+\s+\w+|\S+))) called at /usr/share/perl5/Mail/IMAPClient.pm line 1143
Mail::IMAPClient::idle_data(Mail::IMAPClient=HASH(0x6500ec0)) called at ./FHEM/32_mailcheck.pm line 378
main::mailcheck_Read(HASH(0x2d98c18)) called at fhem.pl line 3550
main::CallFn("mailcheck", "ReadFn", HASH(0x2d98c18)) called at fhem.pl line 708
2018.04.11 01:41:47.636 1: PERL WARNING: Trying command when NOT connected! at /usr/share/perl5/Mail/IMAPClient.pm line 122.
Mail::IMAPClient::LastError(Mail::IMAPClient=HASH(0x6500ec0), "NO not connected") called at /usr/share/perl5/Mail/IMAPClient.pm line 1545
Mail::IMAPClient::_send_line(Mail::IMAPClient=HASH(0x6500ec0), "DONE", 0) called at /usr/share/perl5/Mail/IMAPClient.pm line 1321
Mail::IMAPClient::_imap_command_do(Mail::IMAPClient=HASH(0x6500ec0), HASH(0x668f380), "DONE") called at /usr/share/perl5/Mail/IMAPClient.pm line 1226
Mail::IMAPClient::_imap_command(Mail::IMAPClient=HASH(0x6500ec0), HASH(0x668f380), "DONE") called at /usr/share/perl5/Mail/IMAPClient.pm line 1168
Mail::IMAPClient::done(Mail::IMAPClient=HASH(0x6500ec0)) called at ./FHEM/32_mailcheck.pm line 382
main::mailcheck_Read(HASH(0x2d98c18)) called at fhem.pl line 3550
main::CallFn("mailcheck", "ReadFn", HASH(0x2d98c18)) called at fhem.pl line 708
2018.04.11 01:41:47.639 1: PERL WARNING: Trying command when NOT connected! LastError was: NO not connected at /usr/share/perl5/Mail/IMAPClient.pm line 122.
Mail::IMAPClient::LastError(Mail::IMAPClient=HASH(0x6500ec0), "Error sending 'DONE': NO not connected") called at /usr/share/perl5/Mail/IMAPClient.pm line 1322
Mail::IMAPClient::_imap_command_do(Mail::IMAPClient=HASH(0x6500ec0), HASH(0x668f380), "DONE") called at /usr/share/perl5/Mail/IMAPClient.pm line 1226
Mail::IMAPClient::_imap_command(Mail::IMAPClient=HASH(0x6500ec0), HASH(0x668f380), "DONE") called at /usr/share/perl5/Mail/IMAPClient.pm line 1168
Mail::IMAPClient::done(Mail::IMAPClient=HASH(0x6500ec0)) called at ./FHEM/32_mailcheck.pm line 382
main::mailcheck_Read(HASH(0x2d98c18)) called at fhem.pl line 3550
main::CallFn("mailcheck", "ReadFn", HASH(0x2d98c18)) called at fhem.pl line 708
2018.04.11 01:41:47.641 1: PERL WARNING: Trying command when NOT connected! LastError was: Error sending 'DONE': NO not connected at /usr/share/perl5/Mail/IMAPClient.pm line 122.
Mail::IMAPClient::LastError(Mail::IMAPClient=HASH(0x6500ec0), "Error sending 'DONE': NO not connected") called at /usr/share/perl5/Mail/IMAPClient.pm line 1275
Mail::IMAPClient::_imap_command(Mail::IMAPClient=HASH(0x6500ec0), HASH(0x668f380), "DONE") called at /usr/share/perl5/Mail/IMAPClient.pm line 1168
Mail::IMAPClient::done(Mail::IMAPClient=HASH(0x6500ec0)) called at ./FHEM/32_mailcheck.pm line 382
main::mailcheck_Read(HASH(0x2d98c18)) called at fhem.pl line 3550
main::CallFn("mailcheck", "ReadFn", HASH(0x2d98c18)) called at fhem.pl line 708
2018.04.11 01:41:47.644 1: PERL WARNING: Trying command when NOT connected! at /usr/share/perl5/Mail/IMAPClient.pm line 122.
Mail::IMAPClient::LastError(Mail::IMAPClient=HASH(0x6500ec0), "NO not connected") called at /usr/share/perl5/Mail/IMAPClient.pm line 1545
Mail::IMAPClient::_send_line(Mail::IMAPClient=HASH(0x6500ec0), "438 IDLE", 0) called at /usr/share/perl5/Mail/IMAPClient.pm line 1321
Mail::IMAPClient::_imap_command_do(Mail::IMAPClient=HASH(0x6500ec0), "IDLE", "+") called at /usr/share/perl5/Mail/IMAPClient.pm line 1226
Mail::IMAPClient::_imap_command(Mail::IMAPClient=HASH(0x6500ec0), "IDLE", "+") called at /usr/share/perl5/Mail/IMAPClient.pm line 1119
Mail::IMAPClient::idle(Mail::IMAPClient=HASH(0x6500ec0)) called at ./FHEM/32_mailcheck.pm line 483
main::mailcheck_Read(HASH(0x2d98c18)) called at fhem.pl line 3550
main::CallFn("mailcheck", "ReadFn", HASH(0x2d98c18)) called at fhem.pl line 708
2018.04.11 01:41:47.646 1: PERL WARNING: Trying command when NOT connected! LastError was: NO not connected at /usr/share/perl5/Mail/IMAPClient.pm line 122.
Mail::IMAPClient::LastError(Mail::IMAPClient=HASH(0x6500ec0), "Error sending '438 IDLE': NO not connected") called at /usr/share/perl5/Mail/IMAPClient.pm line 1322
Mail::IMAPClient::_imap_command_do(Mail::IMAPClient=HASH(0x6500ec0), "IDLE", "+") called at /usr/share/perl5/Mail/IMAPClient.pm line 1226
Mail::IMAPClient::_imap_command(Mail::IMAPClient=HASH(0x6500ec0), "IDLE", "+") called at /usr/share/perl5/Mail/IMAPClient.pm line 1119
Mail::IMAPClient::idle(Mail::IMAPClient=HASH(0x6500ec0)) called at ./FHEM/32_mailcheck.pm line 483
main::mailcheck_Read(HASH(0x2d98c18)) called at fhem.pl line 3550
main::CallFn("mailcheck", "ReadFn", HASH(0x2d98c18)) called at fhem.pl line 708
2018.04.11 01:41:47.648 1: PERL WARNING: Trying command when NOT connected! LastError was: Error sending '438 IDLE': NO not connected at /usr/share/perl5/Mail/IMAPClient.pm line 122.
Mail::IMAPClient::LastError(Mail::IMAPClient=HASH(0x6500ec0), "Error sending '438 IDLE': NO not connected") called at /usr/share/perl5/Mail/IMAPClient.pm line 1275
Mail::IMAPClient::_imap_command(Mail::IMAPClient=HASH(0x6500ec0), "IDLE", "+") called at /usr/share/perl5/Mail/IMAPClient.pm line 1119
Mail::IMAPClient::idle(Mail::IMAPClient=HASH(0x6500ec0)) called at ./FHEM/32_mailcheck.pm line 483
main::mailcheck_Read(HASH(0x2d98c18)) called at fhem.pl line 3550
main::CallFn("mailcheck", "ReadFn", HASH(0x2d98c18)) called at fhem.pl line 708


• Das Ganze tritt pro Tag nur ein einziges Mal auf
• Vermutlich verursacht durch eine Verbindungsunterbrechung zur Mailbox, die nach meinen Tests nichts mit dem DSL-reconnect zu tun hat

Könnte man das Verhalten von mailcheck so anpassen, dass geprüft wird, ob überhaupt eine Verbindung besteht?

[justme1968]

hallo udo,

mailcheck prüft schon ob die verbindung aufgebaut ist. siehe z.b. zeile 273.

das problem scheint zu sein das die verbindung auf tcp ip ebene gekillt wird ohne das die verbindung sauber beendet wird und so die imap ebene nichts davon mit bekommt und erst beim tatsächlichen zugriff stolpert.

für einige der zeilen weiter unten gibt es diese prüfung zwar nicht, ich fürchte aber das verhalten wäre genauso.

leider gibt es in Mail::IMAPClient keine hooks um sich ins error handling einzuklinken. als unsauberen hack könntest du aber genau diese eine meldung direkt in IMAPClient.pm vermeiden wenn du dort das Carp::cluck für diesen speziellen fall auskommentierst. das sollte keine weiteren nebeneffekte haben. erst recht weil dieser fall gesondert geprüft wird. wenn du nach Trying command when NOT connected findest du genau diese stelle.

[betateilchen]

Danke für den Tipp, das schaue ich mir mal an. Grundsätzlich sind die Meldungen ja kein Problem, sondern einfach nur "unschön" im Log Kurze Zeit später ist ja wieder Ruhe und die Verbindung steht wieder.

Die Änderung direkt im perl Modul würde vermutlich auch nur bis zum nächsten Update auf linux-Ebene funktionieren.

[justme1968]

Die Änderung direkt im perl Modul würde vermutlich auch nur bis zum nächsten Update auf linux-Ebene funktionieren.

das stimmt leider. allerdings ändert sich Mail::IMAPClient nicht besonders oft.

[Benni]

Guten Morgen zusammen,

Diese Meldungen habe ich normalerweise auch jeden Tag (außer natürlich heute ) im Log. Auch bei mir i.d.R. kein Problem, sondern lediglich "unschön". Das Auskommentieren im Perl-Modul werde ich mal testen.

Ich habe allerdings gelegentlich den auch Fall, erst vorgestern wieder, dass zusätzlich noch folgende Meldungen kommen:

Code Auswählen Erweitern


2018.04.10 04:10:38 1: ERROR: Select error -1 (9), error count= 1
2018.04.10 04:10:38 1: Found and deleted bad fileno for mc.iphone.friends


hier nochmal im Gesamtzusammenhang:

Code Auswählen Erweitern


2018.04.10 04:10:30 1: PERL WARNING: Trying command when NOT connected! at /usr/share/perl5/Mail/IMAPClient.pm line 118
Mail::IMAPClient::LastError('Mail::IMAPClient=HASH(0x1aa09ba8)', 'NO not connected') called at /usr/share/perl5/Mail/IMAPClient.pm line 1454
Mail::IMAPClient::_send_line('Mail::IMAPClient=HASH(0x1aa09ba8)', '15 SELECT INBOX', 0) called at /usr/share/perl5/Mail/IMAPClient.pm line 1304
Mail::IMAPClient::_imap_command_do('Mail::IMAPClient=HASH(0x1aa09ba8)', 'SELECT INBOX') called at /usr/share/perl5/Mail/IMAPClient.pm line 1209
Mail::IMAPClient::_imap_command('Mail::IMAPClient=HASH(0x1aa09ba8)', 'SELECT INBOX') called at /usr/share/perl5/Mail/IMAPClient.pm line 832
Mail::IMAPClient::select('Mail::IMAPClient=HASH(0x1aa09ba8)', 'INBOX') called at ./FHEM/32_mailcheck.pm line 275
main::mailcheck_poll('HASH(0x681c2f0)') called at fhem.pl line 3086
main::HandleTimeout() called at fhem.pl line 618
2018.04.10 04:10:30 1: PERL WARNING: Trying command when NOT connected! at /usr/share/perl5/Mail/IMAPClient.pm line 118
Mail::IMAPClient::LastError('Mail::IMAPClient=HASH(0x1aa09ba8)', 'NO not connected') called at /usr/share/perl5/Mail/IMAPClient.pm line 1454
Mail::IMAPClient::_send_line('Mail::IMAPClient=HASH(0x1aa09ba8)', '16 IDLE', 0) called at /usr/share/perl5/Mail/IMAPClient.pm line 1304
Mail::IMAPClient::_imap_command_do('Mail::IMAPClient=HASH(0x1aa09ba8)', 'IDLE', '+') called at /usr/share/perl5/Mail/IMAPClient.pm line 1209
Mail::IMAPClient::_imap_command('Mail::IMAPClient=HASH(0x1aa09ba8)', 'IDLE', '+') called at /usr/share/perl5/Mail/IMAPClient.pm line 1104
Mail::IMAPClient::idle('Mail::IMAPClient=HASH(0x1aa09ba8)') called at ./FHEM/32_mailcheck.pm line 276
main::mailcheck_poll('HASH(0x681c2f0)') called at fhem.pl line 3086
main::HandleTimeout() called at fhem.pl line 618
2018.04.10 04:10:30 1: ERROR: Select error -1 (9), error count= 0
2018.04.10 04:10:30 1: Found and deleted bad fileno for mc.icloud
2018.04.10 04:10:38 1: PERL WARNING: Trying command when NOT connected! at /usr/share/perl5/Mail/IMAPClient.pm line 118
Mail::IMAPClient::LastError('Mail::IMAPClient=HASH(0x1a326f30)', 'NO not connected') called at /usr/share/perl5/Mail/IMAPClient.pm line 1454
Mail::IMAPClient::_send_line('Mail::IMAPClient=HASH(0x1a326f30)', '15 SELECT INBOX', 0) called at /usr/share/perl5/Mail/IMAPClient.pm line 1304
Mail::IMAPClient::_imap_command_do('Mail::IMAPClient=HASH(0x1a326f30)', 'SELECT INBOX') called at /usr/share/perl5/Mail/IMAPClient.pm line 1209
Mail::IMAPClient::_imap_command('Mail::IMAPClient=HASH(0x1a326f30)', 'SELECT INBOX') called at /usr/share/perl5/Mail/IMAPClient.pm line 832
Mail::IMAPClient::select('Mail::IMAPClient=HASH(0x1a326f30)', 'INBOX') called at ./FHEM/32_mailcheck.pm line 275
main::mailcheck_poll('HASH(0x8b38a20)') called at fhem.pl line 3086
main::HandleTimeout() called at fhem.pl line 618
2018.04.10 04:10:38 1: PERL WARNING: Trying command when NOT connected! at /usr/share/perl5/Mail/IMAPClient.pm line 118
Mail::IMAPClient::LastError('Mail::IMAPClient=HASH(0x1a326f30)', 'NO not connected') called at /usr/share/perl5/Mail/IMAPClient.pm line 1454
Mail::IMAPClient::_send_line('Mail::IMAPClient=HASH(0x1a326f30)', '16 IDLE', 0) called at /usr/share/perl5/Mail/IMAPClient.pm line 1304
Mail::IMAPClient::_imap_command_do('Mail::IMAPClient=HASH(0x1a326f30)', 'IDLE', '+') called at /usr/share/perl5/Mail/IMAPClient.pm line 1209
Mail::IMAPClient::_imap_command('Mail::IMAPClient=HASH(0x1a326f30)', 'IDLE', '+') called at /usr/share/perl5/Mail/IMAPClient.pm line 1104
Mail::IMAPClient::idle('Mail::IMAPClient=HASH(0x1a326f30)') called at ./FHEM/32_mailcheck.pm line 276
main::mailcheck_poll('HASH(0x8b38a20)') called at fhem.pl line 3086
main::HandleTimeout() called at fhem.pl line 618
2018.04.10 04:10:38 1: ERROR: Select error -1 (9), error count= 1
2018.04.10 04:10:38 1: Found and deleted bad fileno for mc.iphone.friends


Wenn dieser Fall auftritt, habe ich das Problem, dass das Mailcheck zwar weiterhin "Logged In" im Status meldet, aber tatsäclich keine Mailabrufe mehr durchführt (durchführen kann?). Erst nach manuellem "set inactive" und anchließendem "set active" und dem dadurch neuerlich diurchgeführten Login läuft alles wieder sauber.

Es ist übrigens wahrscheinlich, dass zu diesem Zeitpunkt gar keine Internetverbindung da war denn das Wunderground-Upload-Modul hat nahe diesem Zeitpunkt ebenfalls einen Fehler gemeldet.

Lässt sich dieser Fall ggf. auch irgendwie abfangen, so dass der Login automatisch wieder erneuert wird? Wegen mir auch gerne durch einen direkten Hack im Perl-Modul (sofern maßgeblich beteiligt).

Danke und Gruß
Benni.

Edit 14.04.2018:

Ich habe mir jetzt erst einmal selbst einen Workaround dazu gebastelt, indem ich ein notify auf den entsprechenden Eintrag im Logfile gesetzt habe, das meine mailchek devices inactive setzt und nach 10 Minuten wieder active.