IMAP with Gmail; Constant lost connection, reconnect; Never fetches an email; Out of debug ideas

Tags: #<Tag:0x00007fc4110d0930>

Hi,

I’m a new user and I’m having trouble getting imap to work with Gmail.

I tried to follow the instructions here - I think I did it right.

Here is what I added to configuration.yaml

sensor:
  - platform: imap_email_content
    server: imap.gmail.com
    port: 993
    name: email_from_rob
    username: !secret gmail_username
    password: !secret gmail_password
    senders:
      - <me>@gmail.com

This is a test example where I’ve used another email address of mine as the sender so that I can test. To be clear, for testing I’m sending from <me>@gmail.com to gmail_username that I have in secrets.yaml

Below is what I get in the log file. Every 30 seconds there are two pairs of “connection lost” and “reconnect succeeded” messages, 1 second apart.

2021-06-09 05:55:59 INFO (SyncWorker_1) [homeassistant.components.imap_email_content.sensor] Connection to imap.gmail.com lost, attempting to reconnect

2021-06-09 05:55:59 INFO (SyncWorker_1) [homeassistant.components.imap_email_content.sensor] Reconnect to imap.gmail.com succeeded, trying last message

2021-06-09 05:56:00 INFO (SyncWorker_5) [homeassistant.components.imap_email_content.sensor] Connection to imap.gmail.com lost, attempting to reconnect

2021-06-09 05:56:00 INFO (SyncWorker_5) [homeassistant.components.imap_email_content.sensor] Reconnect to imap.gmail.com succeeded, trying last message

2021-06-09 05:56:29 INFO (SyncWorker_4) [homeassistant.components.imap_email_content.sensor] Connection to imap.gmail.com lost, attempting to reconnect

2021-06-09 05:56:29 INFO (SyncWorker_4) [homeassistant.components.imap_email_content.sensor] Reconnect to imap.gmail.com succeeded, trying last message

2021-06-09 05:56:30 INFO (SyncWorker_3) [homeassistant.components.imap_email_content.sensor] Connection to imap.gmail.com lost, attempting to reconnect

2021-06-09 05:56:30 INFO (SyncWorker_3) [homeassistant.components.imap_email_content.sensor] Reconnect to imap.gmail.com succeeded, trying last message

I’ve found some reports of similar issues (new user, can’t post link) but not quite the same.

Note in my case I have never been able to get this sensor to update. It’s not related to some specific scenarios about when the email arrives or when HA is reset… I send an email to the monitored address, I confirm it arrived by checking Gmail, but there is no sign of it in HA. The sensor state is always unknown and I never see any of the ‘body’, ‘subject’, etc attributes

From Developer Tools>States:

Other notes:
I am using a Gmail app password.
I haven’t tried specifying a folder, so it should default to Inbox. The emails are staying in the Inbox. I’m not deleting them. The Inbox is not empty.
Using HA OS on Raspberry PI 4. I bought the HW and installed HA last week.

Additional system data:

System Health

version core-2021.6.2
installation_type Home Assistant OS
dev false
hassio true
docker true
virtualenv false
python_version 3.8.9
os_name Linux
os_version 5.4.83-v8
arch aarch64
timezone America/Los_Angeles
Home Assistant Cloud
logged_in false
can_reach_cert_server ok
can_reach_cloud_auth ok
can_reach_cloud ok
Home Assistant Supervisor
host_os Home Assistant OS 5.13
update_channel stable
supervisor_version supervisor-2021.05.4
docker_version 19.03.15
disk_total 57.8 GB
disk_used 2.8 GB
healthy true
supported true
board rpi4-64
supervisor_api ok
version_api ok
installed_addons Visual Studio Code (3.4.1)
Lovelace
dashboards 2
resources 0
views 1
mode storage

Any suggestions for how to fix, or even additional steps I can take to debug, are greatly appreciated - I don’t even know where to go from here.

Maybe stupid question but did you enable imap on your gmail account? It’s disabled by default, It think.

Thanks for your reply Chris.

Yes, I enabled IMAP in Gmail. Another data point: if I intentionally use the wrong password then I get a different error, copied below.

You gave me an idea though… let me see if I can fetch email using another IMAP client. I’ll update when I’ve had a chance to try.

Logger: homeassistant.components.imap_email_content.sensor
Source: components/imap_email_content/sensor.py:96
Integration: imap_email_content (documentation, issues)
First occurred: 7:09:25 AM (2 occurrences)
Last logged: 7:09:25 AM

Failed to login to imap.gmail.com

Indeed. The original error seemed to indicate gmail recognizes you but don’t let you use the service, hence my question.

I had an old Python script that I used previously to access email via imap, so I tried that and it worked perfectly. Same imap server, same port, same username, same password, same search… so the problem doesn’t seem to be on the Gmail side.

Is there any more low-level debug information that I can access that might explain why the connection is lost, or what the outcome of “trying last message” is? I’ve already set the log level to INFO for imap, which is all I know how to do…

Setting it to DEBUG should give you a lot more info.

Doh, sorry - I misremembered the level hierarchy and didn’t double check. Log level is already DEBUG, not INFO (hazards of being a new user)

Edit to add:
The thing is homeassistant.components.imap_email_content.sensor doesn’t give any DEBUG log messages, the only log messages are the INFO ones quoted above. I double checked by setting the default log mode to DEBUG also, and I got a whole lot of DEBUG messages from other components, but no additional messages about imap.

:+1:

Since the log in your first post only shows INFO messages, let’s have a look at the logging section in your config to be sure debugging is enabled. It seems odd that the log doesn’t contain any debug messages. Would you mind posting that?

Crossed replies :slight_smile:

I think my previous response probably answers your question, but to be complete, here’s the logging config as it originally was:

logger:
  default: info
  logs:
    amcrest.http: error
    homeassistant.components.amcrest: error
    homeassistant.components.imap_email_content: debug

The test I just did which I mentioned above was to change default from info to debug, which resulted in a log that looks like this:

2021-06-10 05:11:03 DEBUG (zeroconf-ServiceBrowser__googlecast._tcp.local._246) [zeroconf] Sending (497 bytes #1) <DNSOutgoing:{multicast=True, flags=0, questions=[question[ptr,in,_googlecast._tcp.local.]], answers=[(record[ptr,in,_googlecast._tcp.local.]=120/112,Chromecast-Audio-61181852b2cdb09d1dd86224e0f6abeb._googlecast._tcp.local., 1623301863503.717), (record[ptr,in,_googlecast._tcp.local.]=120/113,Google-Nest-Mini-f11a63b964e7f76818793d90b4574ac4._googlecast._tcp.local., 1623301863503.717), (record[ptr,in,_googlecast._tcp.local.]=120/113,Chromecast-Audio-3e4f1195dc7382f9acbf42ba25b07e3d._googlecast._tcp.local., 1623301863503.717), (record[ptr,in,_googlecast._tcp.local.]=120/113,Chromecast-Audio-a8de01a1c74c29d9dcfe50548bbf6975._googlecast._tcp.local., 1623301863503.717), (record[ptr,in,_googlecast._tcp.local.]=120/113,Google-Nest-Hub-Max-6e33b7dbc2493850ef9317ed0641bd91._googlecast._tcp.local., 1623301863503.717), (record[ptr,in,_googlecast._tcp.local.]=120/113,Google-Cast-Group-4b89dd0cf0a443aa889a65e078bb8040-1._googlecast._tcp.local., 1623301863503.717), (record[ptr,in,_googlecast._tcp.local.]=120/113,Google-Cast-Group-997d360e02134b0ba8fb3df6c7d0db76-1._googlecast._tcp.local., 1623301863503.717)], authorities=[], additionals=[]}> as b'\x00\x00\x00\x00\x00\x01\x00\x07\x00\x00\x00\x00\x0b_googlecast\x04_tcp\x05local\x00\x00\x0c\x00\x01\xc0\x0c\x00\x0c\x00\x01\x00\x00\x00p\x0041Chromecast-Audio-61181852b2cdb09d1dd86224e0f6abeb\xc0\x0c\xc0\x0c\x00\x0c\x00\x01\x00\x00\x00q\x0041Google-Nest-Mini-f11a63b964e7f76818793d90b4574ac4\xc0\x0c\xc0\x0c\x00\x0c\x00\x01\x00\x00\x00q\x0041Chromecast-Audio-3e4f1195dc7382f9acbf42ba25b07e3d\xc0\x0c\xc0\x0c\x00\x0c\x00\x01\x00\x00\x00q\x0041Chromecast-Audio-a8de01a1c74c29d9dcfe50548bbf6975\xc0\x0c\xc0\x0c\x00\x0c\x00\x01\x00\x00\x00q\x0074Google-Nest-Hub-Max-6e33b7dbc2493850ef9317ed0641bd91\xc0\x0c\xc0\x0c\x00\x0c\x00\x01\x00\x00\x00q\x0074Google-Cast-Group-4b89dd0cf0a443aa889a65e078bb8040-1\xc0\x0c\xc0\x0c\x00\x0c\x00\x01\x00\x00\x00q\x0074Google-Cast-Group-997d360e02134b0ba8fb3df6c7d0db76-1\xc0\x0c'...
2021-06-10 05:11:03 DEBUG (zeroconf-Engine-243) [zeroconf] Received from '192.168.1.195':5353 (socket 15): <DNSIncoming:{id=0, flags=0, n_q=1, n_ans=7, n_auth=0, n_add=0, questions=[question[ptr,in,_googlecast._tcp.local.]], answers=[record[ptr,in,_googlecast._tcp.local.]=112/111,Chromecast-Audio-61181852b2cdb09d1dd86224e0f6abeb._googlecast._tcp.local., record[ptr,in,_googlecast._tcp.local.]=113/112,Google-Nest-Mini-f11a63b964e7f76818793d90b4574ac4._googlecast._tcp.local., record[ptr,in,_googlecast._tcp.local.]=113/112,Chromecast-Audio-3e4f1195dc7382f9acbf42ba25b07e3d._googlecast._tcp.local., record[ptr,in,_googlecast._tcp.local.]=113/112,Chromecast-Audio-a8de01a1c74c29d9dcfe50548bbf6975._googlecast._tcp.local., record[ptr,in,_googlecast._tcp.local.]=113/112,Google-Nest-Hub-Max-6e33b7dbc2493850ef9317ed0641bd91._googlecast._tcp.local., record[ptr,in,_googlecast._tcp.local.]=113/112,Google-Cast-Group-4b89dd0cf0a443aa889a65e078bb8040-1._googlecast._tcp.local., record[ptr,in,_googlecast._tcp.local.]=113/112,Google-Cast-Group-997d360e02134b0ba8fb3df6c7d0db76-1._googlecast._tcp.local.]}> (497 bytes) as [b'\x00\x00\x00\x00\x00\x01\x00\x07\x00\x00\x00\x00\x0b_googlecast\x04_tcp\x05local\x00\x00\x0c\x00\x01\xc0\x0c\x00\x0c\x00\x01\x00\x00\x00p\x0041Chromecast-Audio-61181852b2cdb09d1dd86224e0f6abeb\xc0\x0c\xc0\x0c\x00\x0c\x00\x01\x00\x00\x00q\x0041Google-Nest-Mini-f11a63b964e7f76818793d90b4574ac4\xc0\x0c\xc0\x0c\x00\x0c\x00\x01\x00\x00\x00q\x0041Chromecast-Audio-3e4f1195dc7382f9acbf42ba25b07e3d\xc0\x0c\xc0\x0c\x00\x0c\x00\x01\x00\x00\x00q\x0041Chromecast-Audio-a8de01a1c74c29d9dcfe50548bbf6975\xc0\x0c\xc0\x0c\x00\x0c\x00\x01\x00\x00\x00q\x0074Google-Nest-Hub-Max-6e33b7dbc2493850ef9317ed0641bd91\xc0\x0c\xc0\x0c\x00\x0c\x00\x01\x00\x00\x00q\x0074Google-Cast-Group-4b89dd0cf0a443aa889a65e078bb8040-1\xc0\x0c\xc0\x0c\x00\x0c\x00\x01\x00\x00\x00q\x0074Google-Cast-Group-997d360e02134b0ba8fb3df6c7d0db76-1\xc0\x0c']
2021-06-10 05:11:04 DEBUG (SyncWorker_7) [rpi_bad_power] Get under voltage status: 0
2021-06-10 05:11:04 INFO (SyncWorker_2) [homeassistant.components.imap_email_content.sensor] Connection to imap.gmail.com lost, attempting to reconnect
2021-06-10 05:11:04 INFO (SyncWorker_2) [homeassistant.components.imap_email_content.sensor] Reconnect to imap.gmail.com succeeded, trying last message
2021-06-10 05:11:04 INFO (SyncWorker_6) [homeassistant.components.imap_email_content.sensor] Connection to imap.gmail.com lost, attempting to reconnect
2021-06-10 05:11:05 INFO (SyncWorker_6) [homeassistant.components.imap_email_content.sensor] Reconnect to imap.gmail.com succeeded, trying last message
2021-06-10 05:11:07 DEBUG (MainThread) [brother] RAW data: {'1.3.6.1.2.1.43.7.1.1.4.1.1': '2004', '1.3.6.1.4.1.2435.2.3.9.4.2.1.5.5.17.0': 'U1602120810VER.M', '1.3.6.1.4.1.2435.2.3.9.4.2.1.5.5.8.0': ['31010400000001', '32010400000002', '33010400000001', '34010400000001', '6f010400001900', '70010400000384', '71010400000a8c', '72010400002454', '81010400000040', '82010400000009', '8301040000001b', '8401040000005d', '8601040000000a', '87010400000013', '88010400000013', '89010400000013'], '1.3.6.1.4.1.2435.2.3.9.1.1.7.0': 'MFG:Brother;CMD:HBP,BRPJL,URF;MDL:MFC-J5720DW;CLS:PRINTER;CID:Brother Generic Jpeg Type1;URF:SRGB24,W8,CP1,IS1-13-19,MT1-8-11,OB9,PQ4-5,RS200-300,OFU0,V1.3,DM4;', '1.3.6.1.4.1.2435.2.3.9.4.2.1.5.5.11.0': [], '1.3.6.1.2.1.43.10.2.1.4.1.1': '2708', '1.3.6.1.4.1.2435.2.3.9.4.2.1.5.5.1.0': 'U63772A5F273695', '1.3.6.1.4.1.2435.2.3.9.4.2.1.5.4.5.2.0': 'Ink low', '1.3.6.1.2.1.1.3.0': '27494005', '1.3.6.1.4.1.2435.2.3.9.4.2.1.5.5.10.0': ['010104000003a6', '020104000006ee']}
2021-06-10 05:11:07 DEBUG (MainThread) [brother] Data: {'model': 'MFC-J5720DW', 'serial': 'U63772A5F273695', 'firmware': 'U1602120810VER.M', 'status': 'ink low', 'uptime': datetime.datetime(2021, 6, 7, 0, 48, 48, tzinfo=datetime.timezone.utc), 'b/w_counter': 934, 'color_counter': 1774, 'black_ink_status': 1, 'cyan_ink_status': 2, 'magenta_ink_status': 1, 'yellow_ink_status': 1, 'black_ink_remaining': 64, 'cyan_ink_remaining': 9, 'magenta_ink_remaining': 27, 'yellow_ink_remaining': 93, 'black_ink': 64, 'cyan_ink': 9, 'magenta_ink': 27, 'yellow_ink': 93, 'page_counter': 2708}
2021-06-10 05:11:07 DEBUG (MainThread) [homeassistant.components.brother] Finished fetching brother data in 0.094 seconds

Note: plenty of DEBUG messages, but nothing for IMAP.

I don’t think any of the other messages in there are relevant to the problem, but I’m happy to post a bigger chunk of the log if you think there might be some nugget in there.

The imap component uses aioimaplib
Maybe add that one to the logger list in DEBUG. Could be in the form aioimaplib.aioimaplib, not 100% sure which form to use (just add both).

@robdwilson, indeed, I think your edit was made just as I posted. :slight_smile: What @koying said last was going to be me suggestion too: Enable debugging for the underlying library. From the docs, it looks like you can just use this (I’ve only enabled debugging in HA for built-in stuff or custom components):

  logs:
    ...
    aioimaplib: debug

Based on:

    # log level for the `aiohttp` Python package
    aiohttp: error

I started with just aioimaplib but didn’t get any debug messages, so then I also added aioimaplib.aioimaplib but still didn’t get any debug messages. Still just the same imap_email_content INFO messages about connection lost / reconnecting.

Is there a way to check the source code and see if we should expect DEBUG messages from aioimaplib? Or from imap_email_content for that matter.

Here’s the logger config:

logger:
  default: info
  logs:
    amcrest.http: error
    homeassistant.components.amcrest: error
    homeassistant.components.imap_email_content: debug
    aioimaplib: debug
    aioimaplib.aioimaplib: debug

OK - it’s working!
TBH, I now think this was mostly user error…

I looked at aioimaplib and tried it out in Python and realized that it’s not really designed to search a folder for emails, but only to monitor for new emails.

When I was testing I wasn’t sending a new email every time after I reset HA… I had a couple of emails in the Inbox that matched the criteria, so I was thinking that my sensor state should automatically update based on the most recent one as soon as HA started. And then the constant disconnect/reconnect made me think something was going wrong.

But that’s not how it works… I just tried it again, but this time I sent a new message after restarting HA and the message was received and my sensor state and attributes all correctly updated. The disconnect/reconnect messages also stop after the message is received. I also upgraded to the latest HA release yesterday, but I suspect that’s not related to it working now.

The comment I made in my original post was exactly wrong. Maybe I had some other error in the beginning, but for most of this time the problem has been entirely related to when the email arrives and when HA is reset.

Thanks to @koying and @parautenbach for all your inputs.

3 Likes