Endless logging in Console

Florian Rieger

Hi,



I was using the trial version of 1Password 3.8 for a few weeks and everything worked fine.

Yesterday I decided to buy the full version in the MAS (1Password 3.9).

After that I realized a strange behavior.



In the Console.app the 1Password helper seems to send endless messages to the Safari extension.



30.01.12 02:18:16,311 1Password Helper: [39300.079] [ES 0x7fcd32e6d8d0] safari-extension://com.agilebits.onepassword-safari-2bua8c4s2c sendAction: 'lock' [2/8]

30.01.12 02:18:16,312 com.agilebits.onepassword-osx-helper: Jan 30 02:18:16 neo-imac.fritz.box 1Password Helper[249] <Notice>: [39300.079] [ES 0x7fcd32e6d8d0] safari-extension://com.agilebits.onepassword-safari-2bua8c4s2c sendAction: 'lock' [2/8]

30.01.12 02:18:16,315 [0x0-0x1f01f].com.agilebits.onepassword-osx: Jan 30 02:18:16 neo-imac.fritz.box 1Password[242] <Debug>: [39300.079] <AGBonjourMonitor: 0x7fe47aa9cc40> - -[AGBonjourMonitor stop]

30.01.12 02:18:16,547 1Password Helper: [39300.079] [ES 0x7fcd32e6d8d0] safari-extension://com.agilebits.onepassword-safari-2bua8c4s2c sendAction: 'lock' [3/8]

30.01.12 02:18:16,548 com.agilebits.onepassword-osx-helper: Jan 30 02:18:16 neo-imac.fritz.box 1Password Helper[249] <Notice>: [39300.079] [ES 0x7fcd32e6d8d0] safari-extension://com.agilebits.onepassword-safari-2bua8c4s2c sendAction: 'lock' [3/8]

30.01.12 02:18:46,310 com.agilebits.onepassword-osx-helper: Jan 30 02:18:46 neo-imac.fritz.box 1Password Helper[249] <Notice>: [39300.079] [ES 0x7fcd32e6d8d0] safari-extension://com.agilebits.onepassword-safari-2bua8c4s2c sendAction: 'lock' [4/8]

30.01.12 02:18:46,310 1Password Helper: [39300.079] [ES 0x7fcd32e6d8d0] safari-extension://com.agilebits.onepassword-safari-2bua8c4s2c sendAction: 'lock' [4/8]

30.01.12 02:18:46,546 1Password Helper: [39300.079] [ES 0x7fcd32e6d8d0] safari-extension://com.agilebits.onepassword-safari-2bua8c4s2c sendAction: 'lock' [5/8]

30.01.12 02:18:46,546 com.agilebits.onepassword-osx-helper: Jan 30 02:18:46 neo-imac.fritz.box 1Password Helper[249] <Notice>: [39300.079] [ES 0x7fcd32e6d8d0] safari-extension://com.agilebits.onepassword-safari-2bua8c4s2c sendAction: 'lock' [5/8]

30.01.12 02:19:16,309 1Password Helper: [39300.079] [ES 0x7fcd32e6d8d0] safari-extension://com.agilebits.onepassword-safari-2bua8c4s2c sendAction: 'lock' [6/8]

30.01.12 02:19:16,309 com.agilebits.onepassword-osx-helper: Jan 30 02:19:16 neo-imac.fritz.box 1Password Helper[249] <Notice>: [39300.079] [ES 0x7fcd32e6d8d0] safari-extension://com.agilebits.onepassword-safari-2bua8c4s2c sendAction: 'lock' [6/8]

30.01.12 02:19:16,546 1Password Helper: [39300.079] [ES 0x7fcd32e6d8d0] safari-extension://com.agilebits.onepassword-safari-2bua8c4s2c sendAction: 'lock' [7/8]

30.01.12 02:19:16,546 com.agilebits.onepassword-osx-helper: Jan 30 02:19:16 neo-imac.fritz.box 1Password Helper[249] <Notice>: [39300.079] [ES 0x7fcd32e6d8d0] safari-extension://com.agilebits.onepassword-safari-2bua8c4s2c sendAction: 'lock' [7/8]

30.01.12 02:19:46,308 com.agilebits.onepassword-osx-helper: Jan 30 02:19:46 neo-imac.fritz.box 1Password Helper[249] <Notice>: [39300.079] [ES 0x7fcd32e6d8d0] safari-extension://com.agilebits.onepassword-safari-2bua8c4s2c sendAction: 'lock' [8/8]

30.01.12 02:19:46,308 1Password Helper: [39300.079] [ES 0x7fcd32e6d8d0] safari-extension://com.agilebits.onepassword-safari-2bua8c4s2c sendAction: 'lock' [8/8]

30.01.12 02:19:46,545 1Password Helper: [39300.079] [ES 0x7fcd32e6d8d0] safari-extension://com.agilebits.onepassword-safari-2bua8c4s2c sendAction: 'lock' [9/8]

30.01.12 02:19:46,545 com.agilebits.onepassword-osx-helper: Jan 30 02:19:46 neo-imac.fritz.box 1Password Helper[249] <Notice>: [39300.079] [ES 0x7fcd32e6d8d0] safari-extension://com.agilebits.onepassword-safari-2bua8c4s2c sendAction: 'lock' [9/8]

...



The 1Password Helper kept on spamming my system.log until I restarted my mac this morning.



To reproduce this behavior I have to:

1) Restart my Mac

2) Open Safari (1Password extension is installed)

3) Open 1Password.app (Helper is always running)

4) Enter my Login in 1Password.app

5) Wait 5 minutes, until 1Password locks itself automatically

6) Open Console.app and see my system.log explode



I also attached my system.log file.



Is this normal behavior?

How can I stop the endless log entries?

crumbgrabber

I've got the same issue. Been using MAS 1Password for months and months, the problem just started yesterday. In fact, I noticed it because it's preventing my computer from sleeping. Endless logging stops when I disable the Safari extension.

Florian Rieger

Good to know I'm not the only one.

Endless logging prevents my iMac from sleeping, too.

HenryAZ

Mine just started doing the same thing. Since it seems to be associated with "lock", I disabled autolock to stop the nonsense logging until they get it fixed.



Even without this extra bit of logging, 1Password seems to log quite a bit of trivial stuff to system.log. It's almost as if they have debug logging turned on by default.

roustem

I am sorry for the extra logging. We've been debugging various connection issues between the extension and 1Password Helper and the logs were really helpful. I will make sure we reduce the logging as much as possible in the next update.



And thank you for reporting this issue, it seems that the "lock" command is going in circles between the extension and the helper.

Florian Rieger

Thanks for the reply.



Can you reproduce the "lock" circles?

If you need any assistance, just let me know.

roustem

I think I found where it is coming from, thank you for the logs!



I am going to publish a new 3.9.4 beta tonight, [url="http://forum.agilebits.com/index.php?/topic/9967-installing-and-updating-1password-39-betas/"]please see if it fixes the problem for you[/url].

HenryAZ

[quote name='roustem' timestamp='1327949646' post='57856']

I am sorry for the extra logging. We've been debugging various connection issues between the extension and 1Password Helper and the logs were really helpful. I will make sure we reduce the logging as much as possible in the next update.

[/quote]





I just updated to 3.9.4; there does not seem to be any change to 1Password's debug logging. It currently accounts for >75% of my system.log.

roustem

[quote name='HenryAZ' timestamp='1329225931' post='58201']

I just updated to 3.9.4; there does not seem to be any change to 1Password's debug logging. It currently accounts for >75% of my system.log.

[/quote]



Please post a few lines of the log here.



Thank you!

HenryAZ

[quote name='roustem' timestamp='1329249741' post='58214']

Please post a few lines of the log here.



Thank you!

[/quote]





Feb 14 13:05:40 helios 1Password Helper[184]: [39300.079] [ES] Extension Safari-Extension connected from safari-extension://com.agilebits.onepassword-safari-2bua8c4s2c

Feb 14 13:05:40 helios [0x0-0xd00d].com.agilebits.onepassword-osx-helper[184]: Feb 14 13:05:40 helios.7d71.net 1Password Helper[184] <Notice>: [39300.079] [ES] Extension Safari-Extension connected from safari-extension://com.agilebits.onepassword-safari-2bua8c4s2c

Feb 14 13:05:40 helios 1Password Helper[184]: [39300.079] [ES 0x7fda2d14a430] Connected safari-extension://com.agilebits.onepassword-safari-2bua8c4s2c [0/0]

Feb 14 13:05:40 helios [0x0-0xd00d].com.agilebits.onepassword-osx-helper[184]: Feb 14 13:05:40 helios.7d71.net 1Password Helper[184] <Notice>: [39300.079] [ES 0x7fda2d14a430] Connected safari-extension://com.agilebits.onepassword-safari-2bua8c4s2c [0/0]

Feb 14 13:05:40 helios 1Password Helper[184]: [39300.079] [ES 0x7fda2d14a430] org.webkit.nightly.WebKit action: hello [0/2] 184 bytes

Feb 14 13:05:40 helios [0x0-0xd00d].com.agilebits.onepassword-osx-helper[184]: Feb 14 13:05:40 helios.7d71.net 1Password Helper[184] <Notice>: [39300.079] [ES 0x7fda2d14a430] org.webkit.nightly.WebKit action: hello [0/2] 184 bytes

Feb 14 13:05:40 helios 1Password Helper[184]: [39300.079] [ES 0x7fda2d14a430] safari-extension://com.agilebits.onepassword-safari-2bua8c4s2c sendAction: 'welcome' [0/2]

Feb 14 13:05:40 helios [0x0-0xd00d].com.agilebits.onepassword-osx-helper[184]: Feb 14 13:05:40 helios.7d71.net 1Password Helper[184] <Notice>: [39300.079] [ES 0x7fda2d14a430] safari-extension://com.agilebits.onepassword-safari-2bua8c4s2c sendAction: 'welcome' [0/2]

Feb 14 13:05:41 helios 1Password Helper[184]: [39300.079] [ES 0x7fda2d14a430] org.webkit.nightly.WebKit action: syncRequest [1/3] 4339 bytes

Feb 14 13:05:41 helios [0x0-0xd00d].com.agilebits.onepassword-osx-helper[184]: Feb 14 13:05:41 helios.7d71.net 1Password Helper[184] <Notice>: [39300.079] [ES 0x7fda2d14a430] org.webkit.nightly.WebKit action: syncRequest [1/3] 4339 bytes

Feb 14 13:05:41 helios 1Password Helper[184]: [39300.079] [ES 0x7fda2d14a430] syncRequest response: sending 0; requesting: 0 deleting 0.

Feb 14 13:05:41 helios 1Password Helper[184]: [39300.079] [ES 0x7fda2d14a430] safari-extension://com.agilebits.onepassword-safari-2bua8c4s2c sendAction: 'syncReply' [1/3]

Feb 14 13:05:41 helios [0x0-0xd00d].com.agilebits.onepassword-osx-helper[184]: Feb 14 13:05:41 helios.7d71.net 1Password Helper[184] <Notice>: [39300.079] [ES 0x7fda2d14a430] syncRequest response: sending 0; requesting: 0 deleting 0.

Feb 14 13:05:41 helios [0x0-0xd00d].com.agilebits.onepassword-osx-helper[184]: Feb 14 13:05:41 helios.7d71.net 1Password Helper[184] <Notice>: [39300.079] [ES 0x7fda2d14a430] safari-extension://com.agilebits.onepassword-safari-2bua8c4s2c sendAction: 'syncReply' [1/3]

Feb 14 13:05:41 helios 1Password Helper[184]: [39300.079] [ES 0x7fda2d14a430] org.webkit.nightly.WebKit action: syncRequest [2/4] 4339 bytes

Feb 14 13:05:41 helios [0x0-0xd00d].com.agilebits.onepassword-osx-helper[184]: Feb 14 13:05:41 helios.7d71.net 1Password Helper[184] <Notice>: [39300.079] [ES 0x7fda2d14a430] org.webkit.nightly.WebKit action: syncRequest [2/4] 4339 bytes

Feb 14 13:05:41 helios 1Password Helper[184]: [39300.079] [ES 0x7fda2d14a430] syncRequest response: sending 0; requesting: 0 deleting 0.

Feb 14 13:05:41 helios 1Password Helper[184]: [39300.079] [ES 0x7fda2d14a430] safari-extension://com.agilebits.onepassword-safari-2bua8c4s2c sendAction: 'syncReply' [2/4]

Feb 14 13:05:41 helios [0x0-0xd00d].com.agilebits.onepassword-osx-helper[184]: Feb 14 13:05:41 helios.7d71.net 1Password Helper[184] <Notice>: [39300.079] [ES 0x7fda2d14a430] syncRequest response: sending 0; requesting: 0 deleting 0.

Feb 14 13:05:41 helios [0x0-0xd00d].com.agilebits.onepassword-osx-helper[184]: Feb 14 13:05:41 helios.7d71.net 1Password Helper[184] <Notice>: [39300.079] [ES 0x7fda2d14a430] safari-extension://com.agilebits.onepassword-safari-2bua8c4s2c sendAction: 'syncReply' [2/4]

roustem

Thank you!



This is regular logging. It is not the problem that was related to the "lock" request that was constantly send to the extensions in 3.9.3.



I am sorry about the extra logging that you see. There was a major change in 3.9.4 and the browser extensions and we wanted to make sure we can troubleshoot any connection problems that could arise.



I promise to remove as many log messages as possible in 3.9.5.

HenryAZ

[quote name='roustem' timestamp='1329250784' post='58217']

Thank you!



This is regular logging. It is not the problem that was related to the "lock" request that was constantly send to the extensions in 3.9.3.



I am sorry about the extra logging that you see. There was a major change in 3.9.4 and the browser extensions and we wanted to make sure we can troubleshoot any connection problems that could arise.



I promise to remove as many log messages as possible in 3.9.5.

[/quote]



Yes, I am aware it is not related to the "lock" issue that began this thread.



I don't think I would call this "regular" logging, though. When you log every single bit of the conversation (helo, welcome, syncRequest, syncReply), multiple times per "event", I would consider that to be debug logging. Debug does not usually appear in a production environment.



The only reason I even mentioned it is on post #5, above, you said this level of logging would be removed in the "next update". At that point, we were on 3.9.3.



Thanks for your support and a great product.

khad

Thanks for the update (and kind words), Henry! There were some changes which lead to the need for more verbose logging in the current version for troubleshooting purposes. We hope to "quiet down" in the next release and really appreciate your understanding.