"Failed to save message" and hangs

[a613]

I am downloading a folder of email from an inbox.com account, and the script has run beautifully for almost 4GB of data but now it is stuck on a couple messages. I enabled debugging in the config file and ran it again to see why.

It prints Failed to save message due to undefined method[]' for nil:NilClass`. The script doesn't crash but remains running with no output.

[joeyates]

Thanks for the report.

Could you confirm that you are using the latest version (1.0.15)?

[a613]

I think so.

gem update 'imap-backup'
Password:
Updating installed gems
Nothing to update

[a613]

The last few times I've tried to finish downloading that folder, I get a different behaviour: no output whatsoever. When I use Ctrl-C to give up, it always dies with the following trace.

$ imap-backup
D, [2015-02-12T21:25:37.474225 #1470] DEBUG -- : Running backup of account: ******
D, [2015-02-12T21:25:37.474345 #1470] DEBUG -- : Creating IMAP instance: ******, options: {:port=>993, :ssl=>true}
D, [2015-02-12T21:25:40.803321 #1470] DEBUG -- : Logging in: ******/xxxxxxxxxxxx
D, [2015-02-12T21:25:41.984249 #1470] DEBUG -- : Folder: ******
D, [2015-02-12T21:25:47.581546 #1470] DEBUG -- : New messages: 11487
^C/System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/thread.rb:68:in `block in wait': Interrupt
    from /System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/thread.rb:66:in `handle_interrupt'
    from /System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/thread.rb:66:in `wait'
    from /System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/monitor.rb:110:in `wait'
    from /System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/net/imap.rb:1151:in `get_tagged_response'
    from /System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/net/imap.rb:1210:in `block in send_command'
    from /System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/monitor.rb:211:in `mon_synchronize'
    from /System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/net/imap.rb:1192:in `send_command'
    from /System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/net/imap.rb:1363:in `block in fetch_internal'
    from /System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/monitor.rb:211:in `mon_synchronize'
    from /System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/net/imap.rb:1361:in `fetch_internal'
    from /System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/net/imap.rb:805:in `uid_fetch'
    from /Library/Ruby/Gems/2.0.0/gems/imap-backup-1.0.15/lib/imap/backup/account/folder.rb:31:in `fetch'
    from /Library/Ruby/Gems/2.0.0/gems/imap-backup-1.0.15/lib/imap/backup/downloader.rb:18:in `block in run'
    from /Library/Ruby/Gems/2.0.0/gems/imap-backup-1.0.15/lib/imap/backup/downloader.rb:17:in `each'
    from /Library/Ruby/Gems/2.0.0/gems/imap-backup-1.0.15/lib/imap/backup/downloader.rb:17:in `run'
    from /Library/Ruby/Gems/2.0.0/gems/imap-backup-1.0.15/lib/imap/backup/account/connection.rb:45:in `block in run_backup'
    from /Library/Ruby/Gems/2.0.0/gems/imap-backup-1.0.15/lib/imap/backup/account/connection.rb:40:in `each'
    from /Library/Ruby/Gems/2.0.0/gems/imap-backup-1.0.15/lib/imap/backup/account/connection.rb:40:in `run_backup'
    from /Library/Ruby/Gems/2.0.0/gems/imap-backup-1.0.15/bin/imap-backup:65:in `block in <top (required)>'
    from /Library/Ruby/Gems/2.0.0/gems/imap-backup-1.0.15/lib/imap/backup/configuration/list.rb:20:in `block in each_connection'
    from /Library/Ruby/Gems/2.0.0/gems/imap-backup-1.0.15/lib/imap/backup/configuration/list.rb:18:in `each'
    from /Library/Ruby/Gems/2.0.0/gems/imap-backup-1.0.15/lib/imap/backup/configuration/list.rb:18:in `each_connection'
    from /Library/Ruby/Gems/2.0.0/gems/imap-backup-1.0.15/bin/imap-backup:64:in `<top (required)>'
    from /usr/bin/imap-backup:23:in `load'
    from /usr/bin/imap-backup:23:in `<main>'

[joeyates]

It looks like debug log output is not helping.
I've released version 1.0.16 with progressive logging during backup.
Could you update and check what it says?

[a613]

I like the new debug details!

D, [2015-02-17T11:33:45.997780 #1008] DEBUG -- : [*****] 5915 - 4252 bytes
D, [2015-02-17T11:33:47.946716 #1008] DEBUG -- : [*****] 5916 - 5732 bytes
D, [2015-02-17T11:33:54.290620 #1008] DEBUG -- : [*****] 5917 - 172006 bytes
D, [2015-02-17T11:33:56.236607 #1008] DEBUG -- : [*****] 5919 - 5587 bytes
D, [2015-02-17T11:33:59.723113 #1008] DEBUG -- : [*****] 5920 - 61919 bytes
D, [2015-02-17T11:34:03.718306 #1008] DEBUG -- : [*****] 5921 - 111202 bytes

Something changed for the better because thousands more emails are now downloaded without problems. The odd one still fails (as before) but I honestly don't care about them. Here's a failed one for kicks:

W, [2015-02-17T08:39:33.038658 #1008]  WARN -- : [*****] failed to save message 3699:
Received: from ***** by (*****) via
  ***** (*****) with [*****
  SMTP Server] id ***** for *****; Sat, 18 Jan
  2014 05:24:26 -0800
Received: from ***** (***** [*****])
    by ***** (Postfix) with ESMTP id *****
    for <*****>; Sat, 18 Jan 2014 08:24:25 -0500 (EST)
Received: by ***** (Postfix, from userid 501)
    id *****; Sat, 18 Jan 2014 08:24:25 -0500 (EST)
Received: from ***** (***** [*****])
     by ***** (*****) with LMTPA;
     Sat, 18 Jan 2014 08:24:25 -0500
X-Sieve: CMU Sieve 2.4
Subject: {SPAM 05.2} Will *****?

X-Spam: spam
X-Spam-score: 5.2
X-Spam-hits: *****
X-Spam-source: IP='*****', Host='*****', Country='US',
  FromHeader='net', MailFrom='net'
X-Spam-charsets: plain='us-ascii', html='utf-8'
X-Resolved-to: *****
X-Delivered-to: *****
X-Mail-from: *****
Received: from mx1 ([*****])
  by ***** (*****); Sat, 18 Jan 2014 08:24:25 -0500
Received: from ***** (***** [*****])
    by ***** (Postfix) with ESMTP id *****
    for <*****>; Sat, 18 Jan 2014 08:24:23 -0500 (EST)
DKIM-Signature: v=1; a=rsa-sha1; c=relaxed/relaxed; s=ientry; d=*****;
 h=To:From:Reply-To:Subject:Message-ID:List-Unsubscribe:Mime-Version:Content-Type:Date; i=*****;
 bh=*****;
 b=*****
DomainKey-Signature: a=rsa-sha1; c=nofws; q=dns; s=ientry; d=*****;
 b=*****;
Received: by ***** id ***** for <*****>; Sat, 18 Jan 2014 08:24:06 -0500 (envelope-from <*****>)
To: *****
From: "*****" <*****>
Reply-To: <*****>
X-Spam-orig-subject: Will *****?
X-Mailer: iEntrymailer-2
X-iiRefcode: *****
Message-ID: <*****>
List-Unsubscribe: <*****>
Mime-Version: 1.0
X-Campaign-ID: <2095815>
Content-Type: multipart/alternative; boundary=1c08f66a95141aa
Date: Sat, 18 Jan 2014 08:24:23 -0500
X-Spam-Ratio: 6.01
X-Spam-Details: 0;0;2;3.51;0.00
X-Orig-Mail-From: *****

--1c08f66a95141aa
Content-Type: text/plain; charset=us-ascii
Content-Transfer-Encoding: quoted-printable


***** lots of text *****

--1c08f66a95141aa
Content-Type: text/html; charset=utf-8
Content-Transfer-Encoding: quoted-printable

***** lots of html *****

--1c08f66a95141aa--
. undefined method `[]' for nil:NilClass

In the end the program terminated with the following:

D, [2015-02-17T12:57:49.987650 #1008] DEBUG -- : [*****] 6930 - 20118 bytes
D, [2015-02-17T12:57:58.978203 #1008] DEBUG -- : [*****] 6931 - 313876 bytes
D, [2015-02-17T13:02:08.550762 #1008] DEBUG -- : [*****] 6932 - 6964486 bytes
/System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/net/imap.rb:3280:in `next_token': undefined method `dump' for nil:NilClass (NoMethodError)
    from /System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/net/imap.rb:3225:in `lookahead'
    from /System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/net/imap.rb:2219:in `msg_att'
    from /System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/net/imap.rb:2210:in `numeric_response'
    from /System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/net/imap.rb:2152:in `response_untagged'
    from /System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/net/imap.rb:2132:in `response'
    from /System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/net/imap.rb:2058:in `parse'
    from /System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/net/imap.rb:1181:in `get_response'
    from /System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/net/imap.rb:1089:in `receive_responses'
    from /System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/net/imap.rb:1075:in `block in initialize'

When I restart the program, it gets past the place it had died. All in all, these are minor hiccups for the way I'm using the program (one-time backup). Thanks for making it available!