NSDateFormatter errors in Console [Safe to ignore but do let us know where it happens]

Options
DoctorOwl
DoctorOwl
Community Member
edited November 2013 in Mac

In the current 1Password 4 (App Store version) plus Mavericks I saw one of these in Console:

31/10/2013 5:02:43.819 pm 2BUA8C4S2C.com.agilebits.onepassword-osx-helper[225]: 10.4-style NSDateFormatter method called on a 10.0-style formatter, which doesn't work. Break on _NSDateFormatter_Log_New_Methods_On_Old_Formatters to debug. This message will only be logged once.

Nothing bad is happening but I suppose it might want to be fixed at some point if that's a real error.

Comments

  • MikeT
    MikeT
    Options

    Hi @DoctorOwl,

    Do you recall what you were doing just before this message shows up? It looks like we used an old method in our code that we should update. It'd be nice to know where but it's difficult to reproduce because as the message said, it is only "logged once".

    This is safe to ignore, I also see it once in a while from other apps as well, Unibox being the most recent.

  • 365nice
    365nice
    Community Member
    Options

    I saw this after restarting my mac and then launching 1Password and then clicking on favorites (not sure when it actually wrote this message though)

  • MikeT
    MikeT
    Options

    Hi @365nice,

    The console would tell you the exact time and date if you saw it there. I'll check and see if I can reproduce it.

    Thanks!

  • MartyS
    MartyS
    Community Member
    edited February 2014
    Options

    I don't know what's needed to reproduce it, but I have this in my log about 30 minutes after I upgraded to 4.2.BETA-7. So maybe it was soon or immediately after I did my first purposeful search since I did that just before 13:30 (based on a forum post timestamp just after I did the search) and the log entry is for 13:31:01. YMMV

    Edit: it does appear that the forum is about 1 minute behind my system's clock.

  • MartyS
    MartyS
    Community Member
    edited March 2014
    Options

    Perhaps these recent sequences with 4.3.BETA-7 will help:

    3/21/14 11:52:40.322 AM 2BUA8C4S2C.com.agilebits.onepassword4-helper[24369]: 10.4-style NSDateFormatter method called on a 10.0-style formatter, which doesn't work. Break on _NSDateFormatter_Log_New_Methods_On_Old_Formatters to debug. This message will only be logged once.

    3/21/14 11:52:40.327 AM 2BUA8C4S2C.com.agilebits.onepassword4-helper[24369]: 430002 [BACKUP:0x7fed1a49d180:] S backupDatabase:withCompletion: | @backupDatabase

    3/21/14 12:02:08.139 PM 2BUA8C4S2C.com.agilebits.onepassword4-helper[24709]: 10.4-style NSDateFormatter method called on a 10.0-style formatter, which doesn't work. Break on _NSDateFormatter_Log_New_Methods_On_Old_Formatters to debug. This message will only be logged once.

    3/21/14 12:02:08.161 PM 2BUA8C4S2C.com.agilebits.onepassword4-helper[24709]: 430007 [BACKUP:0x7f9db35cdf70:] S backupDatabase:withCompletion: | @backupDatabase

    It appears to be happening for me at the very first data backup after 1Password mini has been restarted. If it isn't easily reproduced in-house, could it be possible that it's data dependent (IE something in my data that you don't have)?

  • Jasper
    Jasper
    edited October 2014
    Options

    Thanks for the follow-up, Marty! I've added that to the existing issue in our tracker. :)

    ref: OPM-1038

  • twicker
    twicker
    Community Member
    edited October 2014
    Options

    Another follow-up (am seeing the same message; sys deets at bottom):
    Likely pertinent Console messages (special codes replaced with "xxx#" for security; am assuming you'll know what they are on your machine):

    10/25/14:
    10:57:43.000 AM bootlog[0]: BOOT_TIME 1414249063 0 _note from me (twicker): all other entries still 10/25/14_ 10:58:25.442 AM xxx1.com.agilebits.onepassword-osx-helper[1101]: 442010 [HELPER:xxx2:<OPHelperAppDelegate: xxx3>] M applicationWillFinishLaunching: | Starting 1Password mini 4.4.2 #442010 built Aug 8 2014 23:54:31 10:58:25.469 AM xxx1.com.agilebits.onepassword-osx-helper[1101]: 442010 [HELPER:xxx2:<OPHelperAppDelegate: xxx3>] M applicationDidFinishLaunching: | Starting 1Password mini 4.4.2 #442010 built Aug 8 2014 23:54:31 10:59:21.828 AM xxx1.com.agilebits.onepassword-osx-helper[1101]: 442010 [EXT:xxx2:<OP3ExtensionServer: xxx4>] M start | [ES3] Starting JSE server on port 6258 10:59:21.829 AM xxx1.com.agilebits.onepassword-osx-helper[1101]: 442010 [EXT:xxx2:<OP4ExtensionServer: xxx5>] M start | [ES4] Starting JSE server on port 6263 11:04:21.850 AM xxx1.com.agilebits.onepassword-osx-helper[1101]: 10.4-style NSDateFormatter method called on a 10.0-style formatter, which doesn't work. Break on _NSDateFormatter_Log_New_Methods_On_Old_Formatters to debug. This message will only be logged once.

    Other info:

    1. MB Pro Retina, 13-inch, Late 2013
      a. 2.4 GHz i5
      b. 8 GB RAM
    2. OS X Mavericks 10.9.5, Security Update 2014-005 (13F34)
    3. Only open apps: Console & Application Monitor
    4. Other extensions:
      a. Flycut (1.5)
      b. Junos Pulse
      c. McAfee Endpoint Protection
      d. aText
    5. 1Password (Mac App Store version, last Mavericks update) had not been opened since boot
    6. 1Password still seems to work fine

    Let me know if you need anything else.

  • MikeT
    MikeT
    Options

    Hi @twicker,

    If you go further in the console when you saw that message, did 1Password create a backup?

  • twicker
    twicker
    Community Member
    Options

    @MikeT - looks like it, assuming "backup" = "sync." If they're different, then no, no backup.

    Most recent messages from the 1Password helper log file (I'm "user1" in all cases; full admin privileges):

    Sun Oct 26 10:47:24 2014| 442010 [XPC:xxx01helplog:] S isValidConnection: | Client verified
    Sun Oct 26 10:47:24 2014| 442010 [XPC:xxx01helplog:] S listener:shouldAcceptNewConnection: | connection accepted
    Sun Oct 26 10:47:30 2014| 442010 [SYNC:xxx01helplog:] S main | > Sync started
    Sun Oct 26 10:47:30 2014| 442010 [SYNC:xxx01helplog:] S main | < Sync finished

    From the main console (which doesn't say anything about a backup, but was the display source for the original error message):

    10/25/14:

    Append to yesterday's post (restarted "xxx#" numbering; note that they're not in order throughout, as I added the 1Password app messages after the helper messages):
    11:06:56.039 AM xxx1.com.agilebits.onepassword-osx-helper[1101]: 442010 [EXT:xxx2:] M webSocketForURI: | [ES4] Extension connected Chrome-Extension 'chrome-extension://xxx4ext / (null)'
    11:15:41.654 AM xpcd[1003]: restored permissions (100600 -> 100700) on /Users/user1/Library/Containers/com.agilebits.onepassword-osx/Container.plist

    Started 1Password Mac App:

    11:15:42.083 AM 1Password[2055]: 442010 [APP:xxx18:] M applicationDidFinishLaunching: | Starting 1Password (AppStore) 4.4.2 #442010 built Aug 8 2014 23:54:59
    11:15:53.665 AM 1Password[2055]: {v1x.#####, y#.######} in {{v2x, y}, {v3, y#}}

    Another Helper msg:

    11:18:37.613 AM xxx1.com.agilebits.onepassword-osx-helper[1101]: 442010 [EXT:xxx20:] M webSocketForURI: | [ES4] Extension connected Safari-Extension 'safari-extension://com.agilebits.onepassword4-safari-xxx1 / (null)'

    Back to App

    11:20:39.379 AM 1Password[2055]: Could not find image named 'vaults-toolbar-overlay'.
    12:01:40.620 PM 1Password[2055]: {v4x.########, y#.####} in {{v5x, y}, {v6, y#}}

    More Helper

    2:01:34.245 PM xxx1.com.agilebits.onepassword-osx-helper[1101]: 442010 [EXT:xxx6:] M webSocketForURI: | [ES4] Extension connected Chrome-Extension 'chrome-extension://xxx4ext / (null)'
    4:19:47.688 PM xxx1.com.agilebits.onepassword-osx-helper[1101]: 442010 [EXT:xxx8:] M webSocketForURI: | [ES4] Extension connected Chrome-Extension 'chrome-extension://xxx4ext / (null)'
    6:31:18.746 PM xxx1.com.agilebits.onepassword-osx-helper[1101]: 442010 [EXT:xxx10:] M webSocketForURI: | [ES4] Extension connected Chrome-Extension 'chrome-extension://xxx4ext / (null)'
    8:46:54.520 PM xxx1.com.agilebits.onepassword-osx-helper[1101]: 442010 [EXT:xxx12:] M webSocketForURI: | [ES4] Extension connected Chrome-Extension 'chrome-extension://xxx4ext / (null)'
    11:06:15.071 PM xxx1.com.agilebits.onepassword-osx-helper[1101]: 442010 [EXT:xxx14:] M webSocketForURI: | [ES4] Extension connected Chrome-Extension 'chrome-extension://xxx4ext / (null)'

    10/26/14:

    1:24:39.653 AM xxx1.com.agilebits.onepassword-osx-helper[1101]: 442010 [EXT:xxx16:] M webSocketForURI: | [ES4] Extension connected Chrome-Extension 'chrome-extension://xxx4ext / (null)'

    Restarted App to see about backups

    10:47:19.720 AM 1Password[14637]: 442010 [APP:xxx21:] M applicationDidFinishLaunching: | Starting 1Password (AppStore) 4.4.2 #442010 built Aug 8 2014 23:54:59

    New Helper message:

    10:47:45.696 AM xxx1.com.agilebits.onepassword-osx-helper[1101]: CoreAnimation: warning, deleted thread with uncommitted CATransaction; set CA_DEBUG_TRANSACTIONS=1 in environment to log backtraces.

  • sjk
    sjk
    1Password Alumni
    Options

    Hi @twicker,

    Thanks those additional log details. I've included them, and what you originally posted, with the related issue in our tracker. Nothing pops out as unusual, although Mike may want to follow up again later.

    I checked for the suspect NSDateFormatter message in logs dating back over a year in a few of my accounts and it's only occurred a couple times. However, one of those instances is on the 24th, just after my last restart of Mavericks before running a backup and installing Yosemite. It originally appeared in /var/log/system.log:

    Oct 24 16:31:22 aura.local 2BUA8C4S2C.com.agilebits.onepassword4-helper[353]: 10.4-style NSDateFormatter method called on a 10.0-style formatter, which doesn't work. Break on _NSDateFormatter_Log_New_Methods_On_Old_Formatters to debug. This message will only be logged once.

    And these are still in ~/Library/Logs/1Password/2BUA8C4S2C.com.agilebits.onepassword4-helper.log (from 1Password mini 4.4.3):

    Fri Oct 24 16:31:22 2014| 443000 [BACKUP:0x7fd7784cca00:<OPBackupManager: 0x7fd7785ccc40>] S backupDatabase:withCompletion: | @backupDatabase Fri Oct 24 16:31:24 2014| 443000 [BACKUP:0x7fd7784cca00:<OPBackupManager: 0x7fd7785ccc40>] S backupDatabase:withCompletion: | Backup completed in 2.539168 seconds. Fri Oct 24 16:31:24 2014| 443000 [BACKUP:0x7fd7784cca00:<OPBackupMonitor: 0x7fd7785dbde0>] S performPeriodicBackupCheck | Backup completed successfully: 'file://localhost/Users/agilebits/Library/Application%20Support/1Password%204/Backups/1Password%202014-10-24%2016_31_22%20(4%20profiles,%202721%20items,%2012%20folders,%204%20attachments).1p4_zip'

    This looks similar to what @MartyS reported in post #6, showing apparent correlation with a backup being run. Adding it to the related tracker issue, too.

  • twicker
    twicker
    Community Member
    Options

    @sjk‌ - thanks! I've been thinking that this would be a low-priority bug (if I hadn't been looking for something else, I'd never have noticed anything unusual - 1pw works great). Just figured I'd let y'all know, help out however I could, and let y'all decide if you needed to squash it. :smile:

    • twicker
  • sjk
    sjk
    1Password Alumni
    Options

    We've appreciated your help with this, @twicker, which has been inspirational to me. :)

    I remember keeping a fairly close eye open for suspicious looking system log messages in earlier OS X releases and could often figure out their cause when spotted. Nowadays there's such a flood of ones that make me go "huh?" that I end up ignoring most and only occasionally cherry pick those that seem troublesome enough to deserve more attention.

This discussion has been closed.