804092 - Continual (re-)writes to addons.sqlite-journal (over NFS?)

Status: RESOLVED WONTFIX

(Firefox :: Extension Compatibility, defect)

Description

[James Pearson]

All our users have home directories on NFS servers - and occasionally one or more users' firefox process will continually re-write to their addons.sqlite-journal file in their profile - resulting in 40+ Mbytes/sec data writes to the NFS server from their clinet workstation

We are using the 32 bit ESR 10.0.7 version of firefox running on CentOS 6 and CentOS 5 64 bit clients

The home directory servers are either Dell boxes running CentOS 5 or Nexenta (Solaris/ZFS) filers

Strace'ing the running firefox processes always shows something like:

2659  _llseek(58, 0, [0], SEEK_SET)     = 0
2659  write(58, "\0\0\0\0\0\0\0\0\0\0\0\0>@\34\234\0\0\0\r\0\0\2\0\0\0\200\0\0\0
\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0
\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0
\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
2659  clock_gettime(CLOCK_MONOTONIC, {801225, 188929185}) = 0
2659  clock_gettime(CLOCK_MONOTONIC, {801225, 188949785}) = 0
2659  _llseek(58, 512, [512], SEEK_SET) = 0
2659  write(58, "\0\0\0\3", 4)          = 4
2659  clock_gettime(CLOCK_MONOTONIC, {801225, 189010876}) = 0
2659  clock_gettime(CLOCK_MONOTONIC, {801225, 189030763}) = 0
2659  _llseek(58, 516, [516], SEEK_SET) = 0
2659  write(58, "\n\0\0\0\2\177\300\0\177\300\177\325\0\0\0\0\0\0\0\0\0\0\0\0\0\
0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\
0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\
0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 32768) = 32768
2659  clock_gettime(CLOCK_MONOTONIC, {801225, 189148893}) = 0
2659  clock_gettime(CLOCK_MONOTONIC, {801225, 189168847}) = 0
2659  _llseek(58, 33284, [33284], SEEK_SET) = 0
2659  write(58, ">@\34\234", 4)         = 4
2659  clock_gettime(CLOCK_MONOTONIC, {801225, 189228603}) = 0
2659  clock_gettime(CLOCK_MONOTONIC, {801225, 189249669}) = 0
2659  _llseek(58, 33288, [33288], SEEK_SET) = 0
2659  write(58, "\0\0\0\2", 4)          = 4
2659  clock_gettime(CLOCK_MONOTONIC, {801225, 189310211}) = 0
2659  clock_gettime(CLOCK_MONOTONIC, {801225, 189330165}) = 0
2659  _llseek(58, 33292, [33292], SEEK_SET) = 0
2659  write(58, "\r\0\0\0\2jH\0m\200jH\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0
\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0
\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0
\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 32768) = 32768
2659  clock_gettime(CLOCK_MONOTONIC, {801225, 189415736}) = 0

which similarly repeats ad infinitum

File descriptor 58 above is addons.sqlite-journal in the user's profile directory on the NFS server

When the user exits firefox, the windows close but the firefox process may not exit - it has to be killed (via 'kill') manually

We have hundreds of users - and I'm currently seeing this issue may be once or twice a week - i.e. not easy to reproduce

Comment 1

[James Pearson]

We have done some further investigation - and it looks like this issue is 'self-inflicted' - the users in question were running firefox on 2 or more machines at the same time - and were manually removing the profile lock files so they could use the same profile on different machines at the same time ...

We have now stopped the users doing this - and the problem has gone away. So this can now be closed.

Comment 2

[Mathias Homann]

please reopen this, I get this all the time, and I am definitely not using FF on more than one computer at the same time.

Comment 3

[Mathias Homann]

as a sidenote, I am seeing this issue with my FF 19.0 on linux at least a couple of times every single day.

Comment 4

[Ioana (away)]

(In reply to Mathias Homann from comment #2)
> please reopen this, I get this all the time, and I am definitely not using
> FF on more than one computer at the same time.

Are you doing the manually removing of the profile lock files?

Comment 5

[Mathias Homann]

nope. just using FF normally. At some point it goes haywire, starts writing like crazy, then I have to kill -9 the process, since quitting closes only the window but doesn't end the actually process under these circumstances.

Of course after -9-ing the process I have to clean up the lock files manually, but only after.

Comment 6

[James Pearson]

Do you have an strace of what it is doing when it gets into this state?

Comment 7

[Mathias Homann]

no, but i sure can grab one next time it happens. shouldn't be long 0.o

Comment 8

[Mathias Homann]

Attachment: a zipfile containing a strace, and the output of lsof

I've attached a zipfile containing a strace and the output of lsof

Comment 9

[James Pearson]

I can't see any writes in that strace output - did you run the strace with the -f option?

Comment 10

[Mathias Homann]

nope. clean forgot. next strace will be -f 0.o

Comment 11

[Bjoern Rost]

just wanted to mention that I saw this or something similar today. A user had previously manually deleted the .parentlock for some reason. Today, his machine was constantly writing to that addons.sqlite-journal. FF19.0.2 on Linux vs a ZFS7120 appliance over NFS3.

I missed to gather an strace this time.

Comment 12

[Mathias Homann]

Attachment: a strace -f of a firefox going crazy

this time i managed to not forget the -f option 0.o

Comment 13

[James Pearson]

That strace output certainly looks similar to what I observed - I assume FD 69 is an addons.sqlite-journal file?

We haven't seen this issue since we stopped the users concerned from removing lock files and running firefox using the same profile multiple times

Are you certain that no other firefox process is accessing this same file at the same time?

e.g. if you kill firefox when this happens and then does the addons.sqlite-journal in question still get updated?

Comment 14

[Mathias Homann]

I don't know which file FD69 was in this particular case...

but i am quite positive no other instance of FF is running on that profile at the same time, and I do not manually remove lock files either.

Next time it happens i'll do a lsof as well again.

Comment 15

[Mathias Homann]

Attachment: zipfile contains lsof and strace of a haywire firefox

zipfile contains lsof and strace of a haywire firefox

Comment 16

[James Pearson]

Do you remove addons.sqlite-journal (and addons.sqlite) before you restart firefox after you've had this problem?

Comment 17

[Mathias Homann]

no, sgould I be doing that?

Comment 18

[James Pearson]

I think you should

In our case, we had at least two processes writing to the same file - so highly likely caused the file to be in a corrupt state ... and maybe what we saw with the high volume of writes _might_ have been because the file was corrupt ...

It might be the case that your addons.sqlite-journal/addons.sqlite got corrupted (for a possibly a completely different reason to ours) and you now see this problem because it is still in this state?

This is just speculation - but I doubt it will harm anything if you remove these files ...

Comment 19

[Sebastian]

I'm experiencing a very similar issue with with Macs running network homes over SMB. In our case it happens with permissions.sqlite-journal and cookies.sqlite-journal. The SMB IO transactions usage goes from our normal 30% to %100 until we fix the issue.

Removing the file stops the re-writes, but the issue comes back after a while. Most of the times it happens with just one file, but sometimes both present the issue.

This is a piece of the iosnoop record:

 0   637 W 1608318720  69632       smbd ??/2mytv66d.default-1393415790171/permissions.sqlite-journal
    0   637 W 1608327120 102400       smbd ??/2mytv66d.default-1393415790171/cookies.sqlite-journal
    0   637 W 1608327520  69632       smbd ??/2mytv66d.default-1393415790171/permissions.sqlite-journal
    0   637 W 1608334408 102400       smbd ??/2mytv66d.default-1393415790171/cookies.sqlite-journal
    0   637 W 1608334680  69632       smbd ??/2mytv66d.default-1393415790171/permissions.sqlite-journal
    0   637 W 1608336632 102400       smbd ??/2mytv66d.default-1393415790171/cookies.sqlite-journal
    0   637 W 1608362568  69632       smbd ??/2mytv66d.default-1393415790171/permissions.sqlite-journal
    0   637 W 1608368720  69632       smbd ??/2mytv66d.default-1393415790171/permissions.sqlite-journal
    0   637 W 1608374528  69632       smbd ??/2mytv66d.default-1393415790171/permissions.sqlite-journal
    0   637 W 1608343776  69632       smbd ??/2mytv66d.default-1393415790171/permissions.sqlite-journal
    0   637 W 1608345688 102400       smbd ??/2mytv66d.default-1393415790171/cookies.sqlite-journal

Comment 20

[Jorge Villalobos [:jorgev] (he/him)]

Mass-closing old Extension Compatibility bugs that relate to legacy add-ons or NPAPI plug-ins. If you think this bug is still valid, please reopen or comment.

Sorry for the bug spam, and happy Friday!