Skip to content
New issue

Have a question about this project? # for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “#”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? # to your account

Frequent OOM issues when importing a mailbox #395

Closed
jpatters opened this issue Aug 26, 2021 · 18 comments
Closed

Frequent OOM issues when importing a mailbox #395

jpatters opened this issue Aug 26, 2021 · 18 comments
Assignees
Labels
bug Something isn't working. storage Related to storage backends.

Comments

@jpatters
Copy link
Contributor

jpatters commented Aug 26, 2021

Describe the bug

I am copying the Sent mailbox, via mac Mail, from my gmail (downloaded over imap) and am getting frequent OOM crashes.

Steps to reproduce

Not really sure. I can't really tell if it is particular messages that are causing the issue or the quantity of them.

Log files

Mac Mail error:

The IMAP command “APPEND” (to Sent) failed with server error: CreateMessage (extractCachedData): unexpected EOF.
syslog
Aug 26 22:28:31 localhost kernel: [10811.574833] systemd-udevd invoked oom-killer: gfp_mask=0x100cca(GFP_HIGHUSER_MOVABLE), order=0, oom_score_adj=-1000
Aug 26 22:28:31 localhost kernel: [10811.574839] CPU: 0 PID: 389 Comm: systemd-udevd Not tainted 5.4.0-80-generic #90-Ubuntu
Aug 26 22:28:31 localhost kernel: [10811.574839] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.12.1-0-ga5cab58e9a3f-prebuilt.qemu.org 04/01/2014
Aug 26 22:28:31 localhost kernel: [10811.574840] Call Trace:
Aug 26 22:28:31 localhost kernel: [10811.574852]  dump_stack+0x6d/0x8b
Aug 26 22:28:31 localhost kernel: [10811.574856]  dump_header+0x4f/0x1eb
Aug 26 22:28:31 localhost kernel: [10811.574858]  oom_kill_process.cold+0xb/0x10
Aug 26 22:28:31 localhost kernel: [10811.574862]  out_of_memory.part.0+0x1df/0x3d0
Aug 26 22:28:31 localhost kernel: [10811.574863]  out_of_memory+0x6d/0xd0
Aug 26 22:28:31 localhost kernel: [10811.574866]  __alloc_pages_slowpath+0xd5e/0xe50
Aug 26 22:28:31 localhost kernel: [10811.574868]  __alloc_pages_nodemask+0x2d0/0x320
Aug 26 22:28:31 localhost kernel: [10811.574870]  alloc_pages_current+0x87/0xe0
Aug 26 22:28:31 localhost kernel: [10811.574873]  __page_cache_alloc+0x72/0x90
Aug 26 22:28:31 localhost kernel: [10811.574874]  pagecache_get_page+0xbf/0x300
Aug 26 22:28:31 localhost kernel: [10811.574876]  filemap_fault+0x6b2/0xa50
Aug 26 22:28:31 localhost kernel: [10811.574878]  ? mem_cgroup_charge_statistics+0x51/0xe0
Aug 26 22:28:31 localhost kernel: [10811.574879]  ? filemap_map_pages+0x24c/0x380
Aug 26 22:28:31 localhost kernel: [10811.574884]  ext4_filemap_fault+0x32/0x50
Aug 26 22:28:31 localhost kernel: [10811.574885]  __do_fault+0x3c/0x130
Aug 26 22:28:31 localhost kernel: [10811.574887]  do_fault+0x24b/0x640
Aug 26 22:28:31 localhost kernel: [10811.574888]  __handle_mm_fault+0x4c5/0x7a0
Aug 26 22:28:31 localhost kernel: [10811.574889]  handle_mm_fault+0xca/0x200
Aug 26 22:28:31 localhost kernel: [10811.574893]  do_user_addr_fault+0x1f9/0x450
Aug 26 22:28:31 localhost kernel: [10811.574894]  __do_page_fault+0x58/0x90
Aug 26 22:28:31 localhost kernel: [10811.574895]  do_page_fault+0x2c/0xe0
Aug 26 22:28:31 localhost kernel: [10811.574897]  do_async_page_fault+0x39/0x70
Aug 26 22:28:31 localhost kernel: [10811.574899]  async_page_fault+0x34/0x40
Aug 26 22:28:31 localhost kernel: [10811.574902] RIP: 0033:0x558eb2d6c970
Aug 26 22:28:31 localhost kernel: [10811.574909] Code: Bad RIP value.
Aug 26 22:28:31 localhost kernel: [10811.574910] RSP: 002b:00007ffd13be9b78 EFLAGS: 00010206
Aug 26 22:28:31 localhost kernel: [10811.574911] RAX: 0000000000000000 RBX: 0000558eb4bdcd28 RCX: 00000000000037a6
Aug 26 22:28:31 localhost kernel: [10811.574912] RDX: 0000558eb4bdcd28 RSI: 0000000000000000 RDI: 0000558eb4bdadd0
Aug 26 22:28:31 localhost kernel: [10811.574912] RBP: 0000558eb4bdadd0 R08: 00007ffd13bfb0f0 R09: 00007ffd13be9ba8
Aug 26 22:28:31 localhost kernel: [10811.574913] R10: 00007ffd13be9ba0 R11: 0000000000002a3b R12: 0000000000000001
Aug 26 22:28:31 localhost kernel: [10811.574913] R13: 0000558eb4bdccf0 R14: 00007ffd13be9c00 R15: 0000000000000000
Aug 26 22:28:31 localhost kernel: [10811.574914] Mem-Info:
Aug 26 22:28:31 localhost kernel: [10811.574917] active_anon:109142 inactive_anon:109595 isolated_anon:0
Aug 26 22:28:31 localhost kernel: [10811.574917]  active_file:7 inactive_file:9 isolated_file:0
Aug 26 22:28:31 localhost kernel: [10811.574917]  unevictable:0 dirty:4 writeback:0 unstable:0
Aug 26 22:28:31 localhost kernel: [10811.574917]  slab_reclaimable:4988 slab_unreclaimable:8554
Aug 26 22:28:31 localhost kernel: [10811.574917]  mapped:404 shmem:422 pagetables:1197 bounce:0
Aug 26 22:28:31 localhost kernel: [10811.574917]  free:12110 free_pcp:263 free_cma:0
Aug 26 22:28:31 localhost kernel: [10811.574919] Node 0 active_anon:436568kB inactive_anon:438380kB active_file:28kB inactive_file:36kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:1616kB dirty:16kB writeback:0kB shmem:1688kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 133120kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
Aug 26 22:28:31 localhost kernel: [10811.574920] Node 0 DMA free:4284kB min:780kB low:972kB high:1164kB active_anon:7436kB inactive_anon:3964kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15992kB managed:15908kB mlocked:0kB kernel_stack:0kB pagetables:16kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Aug 26 22:28:31 localhost kernel: [10811.574922] lowmem_reserve[]: 0 877 877 877 877
Aug 26 22:28:31 localhost kernel: [10811.574923] Node 0 DMA32 free:44156kB min:44272kB low:55340kB high:66408kB active_anon:429132kB inactive_anon:434416kB active_file:28kB inactive_file:36kB unevictable:0kB writepending:16kB present:1032048kB managed:988820kB mlocked:0kB kernel_stack:1836kB pagetables:4772kB bounce:0kB free_pcp:1052kB local_pcp:1052kB free_cma:0kB
Aug 26 22:28:31 localhost kernel: [10811.574926] lowmem_reserve[]: 0 0 0 0 0
Aug 26 22:28:31 localhost kernel: [10811.574927] Node 0 DMA: 5*4kB (UE) 5*8kB (UME) 2*16kB (ME) 3*32kB (UME) 2*64kB (UM) 1*128kB (E) 3*256kB (UME) 2*512kB (ME) 2*1024kB (UE) 0*2048kB 0*4096kB = 4284kB
Aug 26 22:28:31 localhost kernel: [10811.574931] Node 0 DMA32: 385*4kB (UEH) 407*8kB (UEH) 284*16kB (UEH) 182*32kB (UMEH) 125*64kB (UME) 62*128kB (UE) 25*256kB (UME) 3*512kB (ME) 5*1024kB (M) 0*2048kB 0*4096kB = 44156kB
Aug 26 22:28:31 localhost kernel: [10811.574937] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
Aug 26 22:28:31 localhost kernel: [10811.574938] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Aug 26 22:28:31 localhost kernel: [10811.574938] 56606 total pagecache pages
Aug 26 22:28:31 localhost kernel: [10811.574939] 56162 pages in swap cache
Aug 26 22:28:31 localhost kernel: [10811.574940] Swap cache stats: add 364954189, delete 364898027, find 157661067/199756130
Aug 26 22:28:31 localhost kernel: [10811.574940] Free swap  = 0kB
Aug 26 22:28:31 localhost kernel: [10811.574940] Total swap = 524284kB
Aug 26 22:28:31 localhost kernel: [10811.574941] 262010 pages RAM
Aug 26 22:28:31 localhost kernel: [10811.574941] 0 pages HighMem/MovableOnly
Aug 26 22:28:31 localhost kernel: [10811.574941] 10828 pages reserved
Aug 26 22:28:31 localhost kernel: [10811.574942] 0 pages cma reserved
Aug 26 22:28:31 localhost kernel: [10811.574942] 0 pages hwpoisoned
Aug 26 22:28:31 localhost kernel: [10811.574942] Tasks state (memory values in pages):
Aug 26 22:28:31 localhost kernel: [10811.574942] [  pid  ]   uid  tgid total_vm      rss pgtables_bytes swapents oom_score_adj name
Aug 26 22:28:31 localhost kernel: [10811.574946] [    341]     0   341    12852       18   135168      267          -250 systemd-journal
Aug 26 22:28:31 localhost kernel: [10811.574947] [    389]     0   389     5267        8    65536      280         -1000 systemd-udevd
Aug 26 22:28:31 localhost kernel: [10811.574949] [    391]   102   391    22557        3    77824      208             0 systemd-timesyn
Aug 26 22:28:31 localhost kernel: [10811.574950] [    467]   100   467     4602       11    77824      219             0 systemd-network
Aug 26 22:28:31 localhost kernel: [10811.574952] [    478]   101   478     5974       12    86016     1007             0 systemd-resolve
Aug 26 22:28:31 localhost kernel: [10811.574953] [    491]     0   491     2111        1    57344      800             0 haveged
Aug 26 22:28:31 localhost kernel: [10811.574954] [    562]     0   562     1703        0    57344       71             0 cron
Aug 26 22:28:31 localhost kernel: [10811.574956] [    564]   103   564     1861       13    53248      168          -900 dbus-daemon
Aug 26 22:28:31 localhost kernel: [10811.574957] [    571]     0   571     7323       66    90112     1896             0 networkd-dispat
Aug 26 22:28:31 localhost kernel: [10811.574958] [    574]   104   574    56088        0    86016      470             0 rsyslogd
Aug 26 22:28:31 localhost kernel: [10811.574959] [    577]     0   577     4214        0    73728      242             0 systemd-logind
Aug 26 22:28:31 localhost kernel: [10811.574960] [    579]     0   579      948        0    45056       57             0 atd
Aug 26 22:28:31 localhost kernel: [10811.574961] [    640]     0   640     1400        0    49152       33             0 agetty
Aug 26 22:28:31 localhost kernel: [10811.574963] [    649]     0   649    26977        0   110592     1941             0 unattended-upgr
Aug 26 22:28:31 localhost kernel: [10811.574964] [    654]     0   654     1457        0    53248       32             0 agetty
Aug 26 22:28:31 localhost kernel: [10811.574965] [    684]     0   684     3044       12    57344      221         -1000 sshd
Aug 26 22:28:31 localhost kernel: [10811.574966] [   1322]     0  1322    58179        0    81920      227             0 polkitd
Aug 26 22:28:31 localhost kernel: [10811.574968] [  12414]   113 12414    53924        4   163840      504          -900 postgres
Aug 26 22:28:31 localhost kernel: [10811.574969] [  12416]   113 12416    53959        0   172032      532             0 postgres
Aug 26 22:28:31 localhost kernel: [10811.574970] [  12417]   113 12417    53924        3   155648      512             0 postgres
Aug 26 22:28:31 localhost kernel: [10811.574971] [  12418]   113 12418    53924        3   147456      511             0 postgres
Aug 26 22:28:31 localhost kernel: [10811.574973] [  12419]   113 12419    54093        0   159744      608             0 postgres
Aug 26 22:28:31 localhost kernel: [10811.574974] [  12420]   113 12420    17549       14   126976      528             0 postgres
Aug 26 22:28:31 localhost kernel: [10811.574975] [  12421]   113 12421    54032        0   151552      583             0 postgres
Aug 26 22:28:31 localhost kernel: [10811.574976] [  12825]     0 12825     3451        0    61440      367             0 sshd
Aug 26 22:28:31 localhost kernel: [10811.574978] [  12838]     0 12838     4566        1    77824      363             0 systemd
Aug 26 22:28:31 localhost kernel: [10811.574979] [  12839]     0 12839    26030        0    98304     1067             0 (sd-pam)
Aug 26 22:28:31 localhost kernel: [10811.574980] [  12913]     0 12913     2073        0    49152      421             0 bash
Aug 26 22:28:31 localhost kernel: [10811.574981] [  16980]     0 16980     1378        0    49152       47             0 tail
Aug 26 22:28:31 localhost kernel: [10811.574983] [  17230]     0 17230     3044        0    69632      225             0 sshd
Aug 26 22:28:31 localhost kernel: [10811.574984] [  17231]   110 17231     3044        0    69632      226             0 sshd
Aug 26 22:28:31 localhost kernel: [10811.574985] [  17251]   998 17251   597226   161656  2404352   113716             0 maddy
Aug 26 22:28:31 localhost kernel: [10811.574987] [  17256]   113 17256    54199       67   167936      698             0 postgres
Aug 26 22:28:31 localhost kernel: [10811.574988] [  17257]   113 17257    54812      449   184320     1230             0 postgres
Aug 26 22:28:31 localhost kernel: [10811.574989] [  17291]     0 17291     5267        9    61440      285             0 systemd-udevd
Aug 26 22:28:31 localhost kernel: [10811.574991] [  17292]     0 17292     5267        2    61440      298             0 systemd-udevd
Aug 26 22:28:31 localhost kernel: [10811.574993] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=/,mems_allowed=0,global_oom,task_memcg=/system.slice/maddy.service,task=maddy,pid=17251,uid=998
Aug 26 22:28:31 localhost kernel: [10811.575012] Out of memory: Killed process 17251 (maddy) total-vm:2388904kB, anon-rss:646624kB, file-rss:0kB, shmem-rss:0kB, UID:998 pgtables:2348kB oom_score_adj:0
Aug 26 22:28:31 localhost kernel: [10811.656449] oom_reaper: reaped process 17251 (maddy), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB
Aug 26 22:28:31 localhost systemd[1]: maddy.service: Main process exited, code=killed, status=9/KILL
Aug 26 22:28:31 localhost systemd[1]: maddy.service: Failed with result 'signal'.
Aug 26 22:28:31 localhost systemd[1]: maddy.service: Scheduled restart job, restart counter is at 15.
Aug 26 22:28:31 localhost systemd[1]: Stopped maddy mail server.

Configuration file

maddy.conf
## Maddy Mail Server - default configuration file (2021-03-07)
# Suitable for small-scale deployments. Uses its own format for local users DB,
# should be managed via maddyctl utility.
#
# See tutorials at https://maddy.email for guidance on typical
# configuration changes.
#
# See manual pages (also available at https://maddy.email) for reference
# documentation.

# ----------------------------------------------------------------------------
# Base variables

$(hostname) = mx.example.com
$(primary_domain) = example.com
$(local_domains) = $(primary_domain)

# debug yes

tls {
    loader acme {
        hostname mx1.example.com
        email certs@example.com
        agreed true
        challenge dns-01
        dns cloudflare {
            api_token "..."
        }
    }
}

# ----------------------------------------------------------------------------
# Local storage & authentication

# pass_table provides local hashed passwords storage for authentication of
# users. It can be configured to use any "table" module, in default
# configuration a table in SQLite DB is used.
# Table can be replaced to use e.g. a file for passwords. Or pass_table module
# can be replaced altogether to use some external source of credentials (e.g.
# PAM, /etc/shadow file).
#
# If table module supports it (sql_table does) - credentials can be managed
# using 'maddyctl creds' command.

auth.pass_table local_authdb {
    table sql_table {
        driver postgres
        dsn "dbname=maddy user=maddy sslmode=disable"
        table_name passwords
    }
}

# imapsql module stores all indexes and metadata necessary for IMAP using a
# relational database. It is used by IMAP endpoint for mailbox access and
# also by SMTP & Submission endpoints for delivery of local messages.
#
# IMAP accounts, mailboxes and all message metadata can be inspected using
# imap-* subcommands of maddyctl utility.

storage.imapsql local_mailboxes {
    driver postgres
    dsn "dbname=maddy user=maddy sslmode=disable"

    msg_store s3 {
        endpoint us-east-1.linodeobjects.com
        access_key "..."
        secret_key "..."
        bucket jpatters-email
        region US
    }
}

# ----------------------------------------------------------------------------
# SMTP endpoints + message routing

hostname $(hostname)

table.chain local_rewrites {
    optional_step regexp "(.+)\+(.+)@(.+)" "$1@$3"
    optional_step file /etc/maddy/aliases
}

msgpipeline local_routing {
    # Insert handling for special-purpose local domains here.
    # e.g.
    # destination lists.example.org {
    #     deliver_to lmtp tcp://127.0.0.1:8024
    # }

    destination postmaster $(local_domains) {
        modify {
            replace_rcpt &local_rewrites
        }

        deliver_to &local_mailboxes
    }

    default_destination {
        reject 550 5.1.1 "User doesn't exist"
    }
}

smtp tcp://0.0.0.0:25 {
    limits {
        # Up to 20 msgs/sec across max. 10 SMTP connections.
        all rate 20 1s
        all concurrency 10
    }

    auth &local_authdb

    dmarc yes
    check {
        require_mx_record
        dkim
        spf
    }

    source $(local_domains) {
        reject 501 5.1.8 "Use Submission for outgoing SMTP"
    }
    default_source {
        destination postmaster $(local_domains) {
            deliver_to &local_routing
        }
        default_destination {
            reject 550 5.1.1 "User doesn't exist"
        }
    }
}

submission tls://0.0.0.0:465 tcp://0.0.0.0:587 {
    limits {
        # Up to 50 msgs/sec across any amount of SMTP connections.
        all rate 50 1s
    }

    auth &local_authdb

    source $(local_domains) {
        check {
            authorize_sender {
                prepare_email &local_rewrites
                user_to_email identity
            }
        }

        destination postmaster $(local_domains) {
            deliver_to &local_routing
        }
        default_destination {
            modify {
                dkim $(primary_domain) $(local_domains) default
            }
            deliver_to &remote_queue
        }
    }
    default_source {
        reject 501 5.1.8 "Non-local sender domain"
    }
}

target.remote outbound_delivery {
    limits {
        # Up to 20 msgs/sec across max. 10 SMTP connections
        # for each recipient domain.
        destination rate 20 1s
        destination concurrency 10
    }
    mx_auth {
        dane
        mtasts {
            cache fs
            fs_dir mtasts_cache/
        }
        local_policy {
            min_tls_level encrypted
            min_mx_level none
        }
    }
}

target.queue remote_queue {
    target &outbound_delivery

    autogenerated_msg_domain $(primary_domain)
    bounce {
        destination postmaster $(local_domains) {
            deliver_to &local_routing
        }
        default_destination {
            reject 550 5.0.0 "Refusing to send DSNs to non-local addresses"
        }
    }
}

# ----------------------------------------------------------------------------
# IMAP endpoints

imap tls://0.0.0.0:993 tcp://0.0.0.0:143 {
    auth &local_authdb
    storage &local_mailboxes
}

Environment information

  • maddy version: master
  • system: Ubuntu 20.04 Linode 1 CPU 1GB RAM
@jpatters jpatters added the bug Something isn't working. label Aug 26, 2021
@foxcpp foxcpp self-assigned this Aug 27, 2021
@foxcpp
Copy link
Owner

foxcpp commented Aug 27, 2021

The IMAP command “APPEND” (to Sent) failed with server error: CreateMessage (extractCachedData): unexpected EOF.

This one most likely indicates the server encountered a malformed MIME message. Does the error happen multiple times?

@foxcpp
Copy link
Owner

foxcpp commented Aug 27, 2021

07c8495 fixes the resource leak caused by message parse errors. The remaining problem is to figure out whether it is okay for message parse to fail here and how it can be improved or fixed.

Most likely that unexpected EOF error is caused by a missing multipart boundary end. Need to investigate how other IMAP servers handle it (in particular what they return as BODYSTRUCTURE in this case). It would be nice if you can show me an example message that causes this error (you can forward it to fox.cpp@disroot.org if you don't want to post it publicly here).

@jpatters
Copy link
Contributor Author

That was happening while I was moving about 2000 emails so I'm not exactly sure which ones are causing the issue. I will try to find one and send it to you.

@jpatters
Copy link
Contributor Author

It does't seem to be any one message but seems like it might have something to do with messages with no subject.

@jpatters
Copy link
Contributor Author

I was seemingly able to cause a crash and get that error by copying individual messages with no subject. But then when copying the same one again it didn't happen.

@foxcpp foxcpp added the storage Related to storage backends. label Aug 27, 2021
@jpatters
Copy link
Contributor Author

I just tried again from master and am still getting the OOM issues.

@foxcpp
Copy link
Owner

foxcpp commented Aug 28, 2021

Apparently minio-go client we use for S3 turned out to also have severe problems with streaming API causing a lot more memory allocation than necessary.

I will see what I can do to workaround this.

@jpatters
Copy link
Contributor Author

Interesting. Thanks again!

foxcpp added a commit to foxcpp/go-imap-sql that referenced this issue Aug 28, 2021
foxcpp added a commit to foxcpp/go-imap-sql that referenced this issue Aug 28, 2021
foxcpp added a commit that referenced this issue Aug 28, 2021
foxcpp added a commit that referenced this issue Aug 28, 2021
foxcpp added a commit that referenced this issue Aug 28, 2021
Blob size would be unknown ahead of time if message store compression is used (e.g. in imapsql).

Part of #395 fix
@foxcpp
Copy link
Owner

foxcpp commented Aug 28, 2021

1d3e055 and 14a441f should make S3 storage usable with <=1GB of memory.

@jpatters
Copy link
Contributor Author

Just rebuilt and tested this and wow what a difference. No memory issues and performance is way better for importing that mailbox. I'm still getting the EOF errors but at this point it is quite clear that they are unrelated. With the performance gain it will make it easier for me to debug that issue.
Once again, thanks.

@foxcpp
Copy link
Owner

foxcpp commented Aug 29, 2021

Got messages you sent. Strangely, after removing Apple Mail's XML I was able to successfully add them to a IMAP mailbox without any errors. I guess something is off with the way Apple Mail's saved messages.

I would need some more help from you. Enable I/O tracing:

imap tls://0.0.0.0:993 tcp://0.0.0.0:143 {
    auth &local_authdb
    storage &local_mailboxes

    # add these two lines
    debug
    io_debug
}

This should save to log everything IMAP server receives as-is along with any errors it causes. Then try adding messages that cause problems and email me the log (it can contain auth. credentials - you might want to remove these, look for AUTHENTICATE PLAIN or LOGIN lines).

@foxcpp
Copy link
Owner

foxcpp commented Aug 30, 2021

Attached is the logs you requested. The error occurs on line 417. There was a fetch that occurred before and after the logs here. I assumed they weren't relevant but let me know if you want any additional information or logs.

The message as printed in the log seems to be oddly truncated for unknown reason.

Aug 29 20:23:55 localhost maddy[45429]: ize:14px;font-style:normal;font-variant:normal;font-weight:normal;letter-s=
Aug 29 20:23:55 localhost maddy[45429]: pacing:normal;line-height:19px;text-align:left;text-indent:0px;text
Aug 29 20:23:55 localhost maddy[45429]: imap: 59.5007 NO CreateMessage (extractCachedData): unexpected EOF
Aug 29 20:23:55 localhost maddy[45429]: imap: 60.5007 IDLE

To be honest, I have no ideas why this might happen.

@jpatters
Copy link
Contributor Author

I'll try another email client in case it's an issue with Apple mail. I'll let you know what I find.

@jpatters
Copy link
Contributor Author

The same thing happens when transferring the email using thunderbird. So it's not the client mangling it. Looking at the source in gmail, that's how the email ends. It ends with an unfinished img tag. Is maddy parsing the contents of the email? How does it decided when the EOF is expected or not? In gmail it displays the email fine except that there is a partial img tag printed out in plain text at the end.

@foxcpp
Copy link
Owner

foxcpp commented Aug 31, 2021

Is maddy parsing the contents of the email?

maddy expects a well-formed MIME structure. I guess BodyStructure parser should be modified to accept malformed messages and handle them in some way.

CC @emersion

@ptrcnull
Copy link
Contributor

i was able to partially reproduce this issue (the unexpected EOF part) with the following message:

debug log
2022-03-13T06:06:40.446Z imap: 50 authenticate PLAIN
2022-03-13T06:06:40.447Z imap: +
2022-03-13T06:06:40.556Z imap: 50 OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR CHILDREN UNSELECT MOVE IDLE APPENDLIMIT APPENDLIMIT CHILDREN I18NLEVEL=1 SORT THREAD=ORDEREDSUBJECT COMPRESS NAMESPACE] AUTHENTICATE completed
2022-03-13T06:06:40.584Z imap: 51 append "Archive.2021" (\Seen nonjunk) "12-Jan-2021 03:28:03 +0100" {3119+}
Return-Path: <noreply@upstore.net>
Delivered-To: patrycja@ptrcnull.me
Received: from mail.torastian.com
	by mail.torastian.com with LMTP
	id mAvqJ04J/V/jcAAAPp75ag
	(envelope-from <noreply@upstore.net>)
	for <patrycja@ptrcnull.me>; Tue, 12 Jan 2021 03:28:30 +0100
Received: (undefined); Tue, 12 Jan 2021 02:28:29 +0000
Authentication-Results: mail.torastian.com; iprev=fail; spf=pass smtp.mailfrom=upstore.net
Received-SPF: Pass (mail.torastian.com: domain of upstore.net designates 78.47.35.100 as permitted sender) receiver=mail.torastian.com; identity=mailfrom; client-ip=78.47.35.100 helo=upstore.net; envelope-from=<noreply@upstore.net>
Received-SPF: Pass (mail.torastian.com: domain of upstore.net designates 78.47.35.100 as permitted sender) receiver=mail.torastian.com; identity=helo; client-ip=78.47.35.100 helo=upstore.net; envelope-from=<noreply@upstore.net>
X-Haraka-rDNS-OtherIPs: 104.22.4.89 104.22.5.89 172.67.20.47
Received: from upstore.net (upstore.net [78.47.35.100])
	by mail.torastian.com (Haraka) with ESMTP id 14716C1F-569E-4623-B77B-621E171AAAF0.1
	envelope-from <noreply@upstore.net>;
	Tue, 12 Jan 2021 02:28:22 +0000
Received: from noreply by upstore.net with local (Exim 4.80)
	(envelope-from <noreply@upstore.net>)
	id 1kz9Pf-0007Uz-QB
	for upstore@ptrcnull.me; Tue, 12 Jan 2021 02:28:03 +0000
To: upstore@ptrcnull.me
Subject: =?UTF-8?B?WW91ciBwYXNzd29yZCBvbiBVcHN0b3Jl?=
MIME-Version: 1.0
From: =?UTF-8?B?VXBzdG9yZQ==?= <noreply@upstore.net>
Message-Id: a75e9ba43569cc1f20923b39be8b3386@upstore.net
Reply-To: noreply@upstore.net
Content-Type: multipart/mixed; boundary="16104184835FFD0933C3F23"
Date: Tue, 12 Jan 2021 02:28:03 +0000
X-Haraka-Karma: score: -1, good: 0, bad: 1, connections: 1, history: -1, asn_score: -16, asn_connections: 25, asn_good: 3, asn_bad: 19, awards: 131, msg:deny:dnsbl, fail:asn:history, rcpt_to
X-Haraka-ASN: 24940 78.46.0.0/15
X-p0f-Result: os="FreeBSD 8.x" link_type="Ethernet or modem" distance=3 total_conn=2
X-Rspamd-Bar: ++++
X-Rspamd-Report: SUBJ_EXCESS_BASE64(1.5) R_SPF_ALLOW(-0.2) FROM_EXCESS_BASE64(1.5) MIME_GOOD(-0.1) CTYPE_MIXED_BOGUS(1) MIME_HTML_ONLY(0.2) RCVD_NO_TLS_LAST(0.1) MID_MISSING_BRACKETS(0.5)
X-Rspamd-Score: 4.499999
X-Haraka-GeoIP: DE
X-Haraka-GeoIP-Received: 78.47.35.100:DE

--16104184835FFD0933C3F23
Content-Type: text/html; charset=utf-8
Content-Transfer-Encoding: 8bit

<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN" "http://www.w3.org/TR/html4/loose.dtd">
		<html>
		<head>
		<title>Upstore :: Your password on Upstore</title>
		<meta http-equiv="Content-Type" content="text/html; charset=utf-8">
		</head>
		<body link="#00B4EB" alink="#00B4EB" vlink="#00B4EB" text="#444">
		<div><b>Your password on Upstore</b></div>
		<div style="margin-top:10px">y3xgUHaZ<br>
<br>
If you didn't register on website https://upstore.net/ and don't understand what is this message about, just ignore it.</div>
		<hr size="1px" color="#ccc" width="250px" align="left">
		Regards,<br>&nbsp;&nbsp;<a href="http://upstore.net/">Upstore</a> team</a>
		</body>
		</html>


2022-03-13T06:06:40.584Z imap: 
2022-03-13T06:06:40.586Z imap: 51 NO CreateMessage (extractCachedData): unexpected EOF

@charims
Copy link

charims commented May 30, 2022

I've got many hundred spam (and a few valid) emails triggering this unexpected EOF while syncing over some old mail from dovecot. You probably have what you need, but if you do need more sample emails, I am happy to share.

@foxcpp
Copy link
Owner

foxcpp commented Jun 23, 2022

The original issue is resolved, the "unexpected EOF" part is tracked in #466.

@foxcpp foxcpp closed this as completed Jun 23, 2022
AppleSeed95 added a commit to AppleSeed95/sql-imap-v2 that referenced this issue Feb 4, 2024
AppleSeed95 added a commit to AppleSeed95/sql-imap-v2 that referenced this issue Feb 4, 2024
# for free to join this conversation on GitHub. Already have an account? # to comment
Labels
bug Something isn't working. storage Related to storage backends.
Projects
None yet
Development

No branches or pull requests

4 participants