1702416 - [QM_TRY] Failures in dom/localstorage/ActorsParent.cpp:LoadUsageFile

Reporter

Description

•

4 years ago

Clients	Sessions	Hits	Anchor	Stack
1381	1451	1678	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1028:None
425	453	511	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1013:NS_ERROR_FILE_NOT_FOUND
1	1	1	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1017:NS_ERROR_FILE_IS_LOCKED

Jens Stutte [:jstutte]

Reporter

Comment 1

•

4 years ago

Clients	Sessions	Hits	Anchor	Stack
1684	1762	2052	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1028:None
506	534	600	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1013:NS_ERROR_FILE_NOT_FOUND
1	3	3	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1013:NS_ERROR_FILE_NOT_FOUND <- dom/localstorage/ActorsParent.cpp#995:NS_ERROR_FILE_ACCESS_DENIED <- dom/localstorage/ActorsParent.cpp#8127:NS_ERROR_FILE_ACCESS_DENIED <- dom/localstorage/ActorsParent.cpp#8133:NS_ERROR_FILE_ACCESS_DENIED <- dom/localstorage/ActorsParent.cpp#8141:NS_ERROR_FILE_ACCESS_DENIED <- dom/quota/ActorsParent.cpp#4882:NS_ERROR_FILE_ACCESS_DENIED <- dom/quota/ActorsParent.cpp#4954:NS_ERROR_FILE_ACCESS_DENIED <- dom/quota/ActorsParent.cpp#4958:NS_ERROR_FILE_ACCESS_DENIED <- dom/quota/ActorsParent.cpp#4961:NS_ERROR_FILE_ACCESS_DENIED <- dom/quota/ActorsParent.cpp#4750:NS_ERROR_FILE_ACCESS_DENIED <- dom/quota/ActorsParent.cpp#4773:NS_ERROR_FILE_ACCESS_DENIED <- dom/quota/ActorsParent.cpp#4777:NS_ERROR_FILE_ACCESS_DENIED <- dom/quota/ActorsParent.cpp#4780:NS_ERROR_FILE_ACCESS_DENIED <- dom/quota/ActorsParent.cpp#4230:NS_ERROR_FILE_ACCESS_DENIED <- dom/quota/ActorsParent.cpp#4233:NS_ERROR_FILE_ACCESS_DENIED <- dom/quota/ActorsParent.cpp#6234:NS_ERROR_FILE_ACCESS_DENIED

Jens Stutte [:jstutte]

Reporter

Comment 2

•

4 years ago

Clients	Sessions	Hits	Anchor	Stack
2166	2325	2843	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1028:None
722	778	932	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1013:NS_ERROR_FILE_NOT_FOUND

Jens Stutte [:jstutte]

Reporter

Updated

•

4 years ago

Severity: -- → S3

Priority: -- → P2

Jens Stutte [:jstutte]

Reporter

Comment 3

•

4 years ago

Clients	Sessions	Hits	Anchor	Stack
15815	21731	27194	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1028:None
5040	6807	7746	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1013:NS_ERROR_FILE_NOT_FOUND
1	1	1	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1028:None <- dom/localstorage/ActorsParent.cpp#1028:None
1	1	1	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1028:None <- dom/cache/FileUtils.cpp#519:NS_ERROR_FILE_ACCESS_DENIED
1	1	1	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1028:None <- dom/quota/ActorsParent.cpp#9613:NS_ERROR_FAILURE <- dom/quota/ActorsParent.cpp#9613:NS_ERROR_FAILURE <- dom/quota/ActorsParent.cpp#9613:NS_ERROR_FAILURE
1	1	1	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1026:NS_ERROR_FAILURE <- dom/localstorage/ActorsParent.cpp#1000:NS_ERROR_FAILURE <- dom/localstorage/ActorsParent.cpp#8127:NS_ERROR_FAILURE <- dom/localstorage/ActorsParent.cpp#8133:NS_ERROR_FAILURE <- dom/localstorage/ActorsParent.cpp#8141:NS_ERROR_FAILURE <- dom/quota/ActorsParent.cpp#4882:NS_ERROR_FAILURE <- dom/quota/ActorsParent.cpp#4954:NS_ERROR_FAILURE <- dom/quota/ActorsParent.cpp#4958:NS_ERROR_FAILURE <- dom/quota/ActorsParent.cpp#4961:NS_ERROR_FAILURE <- dom/quota/ActorsParent.cpp#4750:NS_ERROR_FAILURE <- dom/quota/ActorsParent.cpp#4773:NS_ERROR_FAILURE <- dom/quota/ActorsParent.cpp#4777:NS_ERROR_FAILURE <- dom/quota/ActorsParent.cpp#4780:NS_ERROR_FAILURE <- dom/quota/ActorsParent.cpp#4230:NS_ERROR_FAILURE <- dom/quota/ActorsParent.cpp#4233:NS_ERROR_FAILURE <- dom/quota/ActorsParent.cpp#6234:NS_ERROR_FAILURE
1	1	1	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1028:None <- dom/quota/ActorsParent.cpp#5320:NS_ERROR_FAILURE <- dom/quota/ActorsParent.cpp#5810:NS_ERROR_FAILURE <- dom/quota/ActorsParent.cpp#6026:NS_ERROR_FAILURE
1	1	1	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1028:None <- dom/cache/FileUtilsImpl.h#74:None <- dom/cache/FileUtilsImpl.h#74:None <- dom/cache/FileUtilsImpl.h#74:None
1	1	1	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1028:None <- dom/localstorage/ActorsParent.cpp#1015:None
1	1	1	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1028:None <- QuotaCommon.h#1212:WIN32(0x45D) <- dom/cache/QuotaClient.cpp#52:WIN32(0x45D) <- dom/cache/QuotaClient.cpp#124:WIN32(0x45D) <- dom/cache/QuotaClient.cpp#437:WIN32(0x45D) <- dom/cache/QuotaClient.cpp#49:WIN32(0x45D) <- dom/cache/QuotaClient.cpp#52:WIN32(0x45D) <- dom/cache/QuotaClient.cpp#478:WIN32(0x45D) <- dom/quota/ActorsParent.cpp#4882:WIN32(0x45D) <- dom/quota/ActorsParent.cpp#4954:WIN32(0x45D) <- dom/quota/ActorsParent.cpp#4958:WIN32(0x45D) <- dom/quota/ActorsParent.cpp#4961:WIN32(0x45D) <- dom/quota/ActorsParent.cpp#4750:WIN32(0x45D) <- dom/quota/ActorsParent.cpp#4773:WIN32(0x45D) <- dom/quota/ActorsParent.cpp#4777:WIN32(0x45D) <- dom/quota/ActorsParent.cpp#4780:WIN32(0x45D) <- dom/quota/ActorsParent.cpp#4230:WIN32(0x45D) <- dom/quota/ActorsParent.cpp#4233:WIN32(0x45D) <- dom/quota/ActorsParent.cpp#6234:WIN32(0x45D)
1	1	1	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1013:NS_ERROR_FILE_NOT_FOUND <- dom/localstorage/ActorsParent.cpp#496:NS_ERROR_STORAGE_BUSY <- dom/localstorage/ActorsParent.cpp#8120:NS_ERROR_STORAGE_BUSY <- dom/localstorage/ActorsParent.cpp#8133:NS_ERROR_STORAGE_BUSY <- dom/localstorage/ActorsParent.cpp#8141:NS_ERROR_STORAGE_BUSY <- dom/quota/ActorsParent.cpp#4882:NS_ERROR_STORAGE_BUSY <- dom/quota/ActorsParent.cpp#4954:NS_ERROR_STORAGE_BUSY <- dom/quota/ActorsParent.cpp#4958:NS_ERROR_STORAGE_BUSY <- dom/quota/ActorsParent.cpp#4961:NS_ERROR_STORAGE_BUSY <- dom/quota/ActorsParent.cpp#4750:NS_ERROR_STORAGE_BUSY <- dom/quota/ActorsParent.cpp#4773:NS_ERROR_STORAGE_BUSY <- dom/quota/ActorsParent.cpp#4777:NS_ERROR_STORAGE_BUSY <- dom/quota/ActorsParent.cpp#4780:NS_ERROR_STORAGE_BUSY <- dom/quota/ActorsParent.cpp#4230:NS_ERROR_STORAGE_BUSY <- dom/quota/ActorsParent.cpp#4233:NS_ERROR_STORAGE_BUSY <- dom/quota/ActorsParent.cpp#6234:NS_ERROR_STORAGE_BUSY
1	1	1	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1028:None <- dom/quota/ActorsParent.cpp#2582:WIN32(0x45D) <- dom/quota/ActorsParent.cpp#4555:WIN32(0x45D) <- dom/quota/ActorsParent.cpp#4628:WIN32(0x45D)
1	1	1	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1013:NS_ERROR_FILE_NOT_FOUND <- dom/quota/QuotaCommon.cpp#201:NS_ERROR_STORAGE_IOERR <- dom/quota/ActorsParent.cpp#4178:NS_ERROR_STORAGE_IOERR <- dom/quota/ActorsParent.cpp#4195:NS_ERROR_STORAGE_IOERR <- dom/quota/ActorsParent.cpp#6234:NS_ERROR_STORAGE_IOERR
1	1	1	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1026:NS_ERROR_FAILURE

Jens Stutte [:jstutte]

Reporter

Comment 4

•

4 years ago

Looking at LoadUsageFile I wonder, why we do not see NS_ERROR_FILE_CORRUPTED in our telemetry.

Flags: needinfo?(jvarga)

Simon Giesecke [:sg] [he/him]

Comment 5

•

4 years ago

That's a limitation of the QM_TRY macros at the moment: a custom return value is not passed to the handler function. This is because a custom return value is not necessarily an error. Maybe it could be done in case it is an error.

Jan Varga [:janv]

Comment 6

•

4 years ago

Hm, but if we report the custom error instead, we won't know what was the original error. The custom error is clear from inspecting the code, but the original error has to be reported to be seen (it's simpler than that in the case of OkIf of course, but not in general). The custom error is propagated, so it should be visible in the stack. Some stacks are currently broken and Jens is working on a fix, we will see then.

We could also add a second result to the event if needed.

Flags: needinfo?(jvarga)

Jens Stutte [:jstutte]

Reporter

Comment 7

•

4 years ago

Adjusting the script yields now (with data from 5 days back from today, so differences in numbers are expected):

Clients	Sessions	Hits	Anchor	Stack
5235	5742	7463	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1028:None
1746	1896	2158	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1013:NS_ERROR_FILE_NOT_FOUND
1127	1216	1583	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1028:None
429	462	574	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1013:NS_ERROR_FILE_NOT_FOUND
2	2	3	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1017:NS_ERROR_FILE_IS_LOCKED
1	1	1	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1015:None
1	1	1	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1028:None
1	1	2	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1017:NS_ERROR_FILE_IS_LOCKED
1	1	1	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1017:NS_ERROR_FILE_IS_LOCKED <- dom/localstorage/ActorsParent.cpp#995:NS_ERROR_FILE_IS_LOCKED <- dom/localstorage/ActorsParent.cpp#8127:NS_ERROR_FILE_IS_LOCKED <- dom/localstorage/ActorsParent.cpp#8133:NS_ERROR_FILE_IS_LOCKED <- dom/localstorage/ActorsParent.cpp#8141:NS_ERROR_FILE_IS_LOCKED <- dom/quota/ActorsParent.cpp#4882:NS_ERROR_FILE_IS_LOCKED <- dom/quota/ActorsParent.cpp#4954:NS_ERROR_FILE_IS_LOCKED <- dom/quota/ActorsParent.cpp#4958:NS_ERROR_FILE_IS_LOCKED <- dom/quota/ActorsParent.cpp#4961:NS_ERROR_FILE_IS_LOCKED <- dom/quota/ActorsParent.cpp#4750:NS_ERROR_FILE_IS_LOCKED <- dom/quota/ActorsParent.cpp#4773:NS_ERROR_FILE_IS_LOCKED <- dom/quota/ActorsParent.cpp#4777:NS_ERROR_FILE_IS_LOCKED <- dom/quota/ActorsParent.cpp#4780:NS_ERROR_FILE_IS_LOCKED <- dom/quota/ActorsParent.cpp#4230:NS_ERROR_FILE_IS_LOCKED <- dom/quota/ActorsParent.cpp#4233:NS_ERROR_FILE_IS_LOCKED <- dom/quota/ActorsParent.cpp#6234:NS_ERROR_FILE_IS_LOCKED

The last stack remains suspicious, but looking in the data it is all happening in the same session with the same event_timestamp and apparently we did not identify the location dom/localstorage/ActorsParent.cpp#995:NS_ERROR_FILE_IS_LOCKED as a topmost frame elsewhere.

Jan Varga [:janv]

Comment 8

•

4 years ago

Ok, the last entry in the table (the one with many frames) looks almost perfect. The first frame dom/localstorage/ActorsParent.cpp#1017:NS_ERROR_FILE_IS_LOCKED shouldn't be there, otherwise the stack makes sense to me, except it probably belongs to a different bug (Failures in dom/localstorage/ActorsParent.cpp:UpdateUsageFile).

I wonder why some stacks are so small (with one frame), for example the first entry in the table dom/localstorage/ActorsParent.cpp#1028:None

Jens Stutte [:jstutte]

Reporter

Comment 9

•

4 years ago

(In reply to Jan Varga [:janv] from comment #8)

Ok, the last entry in the table (the one with many frames) looks almost perfect. The first frame dom/localstorage/ActorsParent.cpp#1017:NS_ERROR_FILE_IS_LOCKED shouldn't be there, otherwise the stack makes sense to me, except it probably belongs to a different bug (Failures in dom/localstorage/ActorsParent.cpp:UpdateUsageFile).

As said, in that case the first frame should be a 1 frame stack, and the rest another one. But for that specific location (combination of build/source/line) we found no other occurrence of dom/localstorage/ActorsParent.cpp#995:NS_ERROR_FILE_IS_LOCKED in our data as a so called topmost frame. And the two events are happening right in the same moment on the same session. It is an edge case we cannot really resolve, I fear.

I wonder why some stacks are so small (with one frame), for example the first entry in the table dom/localstorage/ActorsParent.cpp#1028:None

I see only one frame for the entire session in question there, at least in my downloaded data. So the stack analysis can definitely not find more frames here. Might this be truncated during propagation if we have the unforeseen "None" value in QM_TRY ?

Jan Varga [:janv]

Comment 10

•

4 years ago

(In reply to Jens Stutte [:jstutte] from comment #9)

(In reply to Jan Varga [:janv] from comment #8)

Ok, the last entry in the table (the one with many frames) looks almost perfect. The first frame dom/localstorage/ActorsParent.cpp#1017:NS_ERROR_FILE_IS_LOCKED shouldn't be there, otherwise the stack makes sense to me, except it probably belongs to a different bug (Failures in dom/localstorage/ActorsParent.cpp:UpdateUsageFile).

As said, in that case the first frame should be a 1 frame stack, and the rest another one. But for that specific location (combination of build/source/line) we found no other occurrence of dom/localstorage/ActorsParent.cpp#995:NS_ERROR_FILE_IS_LOCKED in our data as a so called topmost frame. And the two events are happening right in the same moment on the same session. It is an edge case we cannot really resolve, I fear.

Hm, but then there must be a hole in the sequence numbers ?
I mean they are growing, but the sequence number for dom/localstorage/ActorsParent.cpp#995:NS_ERROR_FILE_IS_LOCKED is not the sequence number for dom/localstorage/ActorsParent.cpp#1017:NS_ERROR_FILE_IS_LOCKED + 1

I wonder why some stacks are so small (with one frame), for example the first entry in the table dom/localstorage/ActorsParent.cpp#1028:None

I see only one frame for the entire session in question there, at least in my downloaded data. So the stack analysis can definitely not find more frames here. Might this be truncated during propagation if we have the unforeseen "None" value in QM_TRY ?

Hm, I think it can be the case when other frames get truncated by the LIMIT clause in the SQL query.

Jens Stutte [:jstutte]

Reporter

Comment 11

•

4 years ago

•

Edited

(In reply to Jan Varga [:janv] from comment #10)

Hm, but then there must be a hole in the sequence numbers ?
I mean they are growing, but the sequence number for dom/localstorage/ActorsParent.cpp#995:NS_ERROR_FILE_IS_LOCKED is not the sequence number for dom/localstorage/ActorsParent.cpp#1017:NS_ERROR_FILE_IS_LOCKED + 1

No, there isn't:

    {
        "submit_timeabs": 1617701012444,
        "session_start_time": "2021-04-06T08:22:00",
        "submission_date": "2021-04-06",
        "build_id": "20210401185811",
        "client_id": "77a8b351-654a-4cde-b366-0534a7aa2f8d",
        "session_id": "4752365e-a140-4dbc-ad38-74be7aa92477",
        "event_timestamp": 8315,
        "seq": 1,
        "context": "Initialization::TemporaryStorage",
        "source_file": "dom/localstorage/ActorsParent.cpp",
        "source_line": "1017",
        "severity": "ERROR",
        "result": "NS_ERROR_FILE_IS_LOCKED"
    },
    {
        "submit_timeabs": 1617701012444,
        "session_start_time": "2021-04-06T08:22:00",
        "submission_date": "2021-04-06",
        "build_id": "20210401185811",
        "client_id": "77a8b351-654a-4cde-b366-0534a7aa2f8d",
        "session_id": "4752365e-a140-4dbc-ad38-74be7aa92477",
        "event_timestamp": 8315,
        "seq": 2,
        "context": "Initialization::TemporaryStorage",
        "source_file": "dom/localstorage/ActorsParent.cpp",
        "source_line": "995",
        "severity": "ERROR",
        "result": "NS_ERROR_FILE_IS_LOCKED"
    },
    {
        "submit_timeabs": 1617701012444,
        "session_start_time": "2021-04-06T08:22:00",
        "submission_date": "2021-04-06",
        "build_id": "20210401185811",
        "client_id": "77a8b351-654a-4cde-b366-0534a7aa2f8d",
        "session_id": "4752365e-a140-4dbc-ad38-74be7aa92477",
        "event_timestamp": 8315,
        "seq": 3,
        "context": "Initialization::TemporaryStorage",
        "source_file": "dom/localstorage/ActorsParent.cpp",
        "source_line": "8127",
        "severity": "ERROR",
        "result": "NS_ERROR_FILE_IS_LOCKED"
    },
    {
        "submit_timeabs": 1617701012444,
        "session_start_time": "2021-04-06T08:22:00",
        "submission_date": "2021-04-06",
        "build_id": "20210401185811",
        "client_id": "77a8b351-654a-4cde-b366-0534a7aa2f8d",
        "session_id": "4752365e-a140-4dbc-ad38-74be7aa92477",
        "event_timestamp": 8315,
        "seq": 4,
        "context": "Initialization::TemporaryStorage",
        "source_file": "dom/localstorage/ActorsParent.cpp",
        "source_line": "8133",
        "severity": "ERROR",
        "result": "NS_ERROR_FILE_IS_LOCKED"
    },
    {
        "submit_timeabs": 1617701012444,
        "session_start_time": "2021-04-06T08:22:00",
        "submission_date": "2021-04-06",
        "build_id": "20210401185811",
        "client_id": "77a8b351-654a-4cde-b366-0534a7aa2f8d",
        "session_id": "4752365e-a140-4dbc-ad38-74be7aa92477",
        "event_timestamp": 8315,
        "seq": 5,
        "context": "Initialization::TemporaryStorage",
        "source_file": "dom/localstorage/ActorsParent.cpp",
        "source_line": "8141",
        "severity": "ERROR",
        "result": "NS_ERROR_FILE_IS_LOCKED"
    },
    {
        "submit_timeabs": 1617701012444,
        "session_start_time": "2021-04-06T08:22:00",
        "submission_date": "2021-04-06",
        "build_id": "20210401185811",
        "client_id": "77a8b351-654a-4cde-b366-0534a7aa2f8d",
        "session_id": "4752365e-a140-4dbc-ad38-74be7aa92477",
        "event_timestamp": 8315,
        "seq": 6,
        "context": "Initialization::TemporaryStorage",
        "source_file": "dom/quota/ActorsParent.cpp",
        "source_line": "4882",
        "severity": "ERROR",
        "result": "NS_ERROR_FILE_IS_LOCKED"
    },
    {
        "submit_timeabs": 1617701012444,
        "session_start_time": "2021-04-06T08:22:00",
        "submission_date": "2021-04-06",
        "build_id": "20210401185811",
        "client_id": "77a8b351-654a-4cde-b366-0534a7aa2f8d",
        "session_id": "4752365e-a140-4dbc-ad38-74be7aa92477",
        "event_timestamp": 8315,
        "seq": 7,
        "context": "Initialization::TemporaryStorage",
        "source_file": "dom/quota/ActorsParent.cpp",
        "source_line": "4954",
        "severity": "ERROR",
        "result": "NS_ERROR_FILE_IS_LOCKED"
    },
    {
        "submit_timeabs": 1617701012444,
        "session_start_time": "2021-04-06T08:22:00",
        "submission_date": "2021-04-06",
        "build_id": "20210401185811",
        "client_id": "77a8b351-654a-4cde-b366-0534a7aa2f8d",
        "session_id": "4752365e-a140-4dbc-ad38-74be7aa92477",
        "event_timestamp": 8315,
        "seq": 8,
        "context": "Initialization::TemporaryStorage",
        "source_file": "dom/quota/ActorsParent.cpp",
        "source_line": "4958",
        "severity": "ERROR",
        "result": "NS_ERROR_FILE_IS_LOCKED"
    },
    {
        "submit_timeabs": 1617701012444,
        "session_start_time": "2021-04-06T08:22:00",
        "submission_date": "2021-04-06",
        "build_id": "20210401185811",
        "client_id": "77a8b351-654a-4cde-b366-0534a7aa2f8d",
        "session_id": "4752365e-a140-4dbc-ad38-74be7aa92477",
        "event_timestamp": 8315,
        "seq": 9,
        "context": "Initialization::TemporaryStorage",
        "source_file": "dom/quota/ActorsParent.cpp",
        "source_line": "4961",
        "severity": "ERROR",
        "result": "NS_ERROR_FILE_IS_LOCKED"
    },
    {
        "submit_timeabs": 1617701012444,
        "session_start_time": "2021-04-06T08:22:00",
        "submission_date": "2021-04-06",
        "build_id": "20210401185811",
        "client_id": "77a8b351-654a-4cde-b366-0534a7aa2f8d",
        "session_id": "4752365e-a140-4dbc-ad38-74be7aa92477",
        "event_timestamp": 8315,
        "seq": 10,
        "context": "Initialization::TemporaryStorage",
        "source_file": "dom/quota/ActorsParent.cpp",
        "source_line": "4750",
        "severity": "ERROR",
        "result": "NS_ERROR_FILE_IS_LOCKED"
    },
    {
        "submit_timeabs": 1617701012444,
        "session_start_time": "2021-04-06T08:22:00",
        "submission_date": "2021-04-06",
        "build_id": "20210401185811",
        "client_id": "77a8b351-654a-4cde-b366-0534a7aa2f8d",
        "session_id": "4752365e-a140-4dbc-ad38-74be7aa92477",
        "event_timestamp": 8315,
        "seq": 11,
        "context": "Initialization::TemporaryStorage",
        "source_file": "dom/quota/ActorsParent.cpp",
        "source_line": "4773",
        "severity": "ERROR",
        "result": "NS_ERROR_FILE_IS_LOCKED"
    },
    {
        "submit_timeabs": 1617701012444,
        "session_start_time": "2021-04-06T08:22:00",
        "submission_date": "2021-04-06",
        "build_id": "20210401185811",
        "client_id": "77a8b351-654a-4cde-b366-0534a7aa2f8d",
        "session_id": "4752365e-a140-4dbc-ad38-74be7aa92477",
        "event_timestamp": 8315,
        "seq": 12,
        "context": "Initialization::TemporaryStorage",
        "source_file": "dom/quota/ActorsParent.cpp",
        "source_line": "4777",
        "severity": "ERROR",
        "result": "NS_ERROR_FILE_IS_LOCKED"
    },
    {
        "submit_timeabs": 1617701012444,
        "session_start_time": "2021-04-06T08:22:00",
        "submission_date": "2021-04-06",
        "build_id": "20210401185811",
        "client_id": "77a8b351-654a-4cde-b366-0534a7aa2f8d",
        "session_id": "4752365e-a140-4dbc-ad38-74be7aa92477",
        "event_timestamp": 8315,
        "seq": 13,
        "context": "Initialization::TemporaryStorage",
        "source_file": "dom/quota/ActorsParent.cpp",
        "source_line": "4780",
        "severity": "ERROR",
        "result": "NS_ERROR_FILE_IS_LOCKED"
    },
    {
        "submit_timeabs": 1617701012444,
        "session_start_time": "2021-04-06T08:22:00",
        "submission_date": "2021-04-06",
        "build_id": "20210401185811",
        "client_id": "77a8b351-654a-4cde-b366-0534a7aa2f8d",
        "session_id": "4752365e-a140-4dbc-ad38-74be7aa92477",
        "event_timestamp": 8315,
        "seq": 14,
        "context": "Initialization::TemporaryStorage",
        "source_file": "dom/quota/ActorsParent.cpp",
        "source_line": "4230",
        "severity": "ERROR",
        "result": "NS_ERROR_FILE_IS_LOCKED"
    },
    {
        "submit_timeabs": 1617701012444,
        "session_start_time": "2021-04-06T08:22:00",
        "submission_date": "2021-04-06",
        "build_id": "20210401185811",
        "client_id": "77a8b351-654a-4cde-b366-0534a7aa2f8d",
        "session_id": "4752365e-a140-4dbc-ad38-74be7aa92477",
        "event_timestamp": 8315,
        "seq": 15,
        "context": "Initialization::TemporaryStorage",
        "source_file": "dom/quota/ActorsParent.cpp",
        "source_line": "4233",
        "severity": "ERROR",
        "result": "NS_ERROR_FILE_IS_LOCKED"
    },
    {
        "submit_timeabs": 1617701012444,
        "session_start_time": "2021-04-06T08:22:00",
        "submission_date": "2021-04-06",
        "build_id": "20210401185811",
        "client_id": "77a8b351-654a-4cde-b366-0534a7aa2f8d",
        "session_id": "4752365e-a140-4dbc-ad38-74be7aa92477",
        "event_timestamp": 8315,
        "seq": 16,
        "context": "Initialization::TemporaryStorage",
        "source_file": "dom/quota/ActorsParent.cpp",
        "source_line": "6234",
        "severity": "ERROR",
        "result": "NS_ERROR_FILE_IS_LOCKED"
    },

Hm, I think it can be the case when other frames get truncated by the LIMIT clause in the SQL query.

No, the data has been fetched without touching the limit (217703 rows against 600000 limit). And the script is excluding sessions that do not start with sequence number "1", too, in order to avoid noise. I also cross-checked with the database, there is definitely just one record for that session:

1,617,695,170,954	
2021-04-06 06:45	
2021-04-06	
20210401185811	
004219d9-5cc5-46fb-91f4-7219943fb15a
53,305	
fa40069c-23bd-4b06-88db-e3f7b9cf5cb6
1	
Initialization::TemporaryStorage
dom/localstorage/ActorsParent.cpp
1028
ERROR
(null)

Jan Varga [:janv]

Comment 12

•

4 years ago

Ok, thanks for the data, I'll take a look again.

Jan Varga [:janv]

Comment 13

•

4 years ago

Oh, I finally see it :) dom/localstorage/ActorsParent.cpp#1017:NS_ERROR_FILE_IS_LOCKED fails first and it was called by https://hg.mozilla.org/releases/mozilla-beta/annotate/e4ba3bcb9d881637a2c30daf7fa9f544087ba181/dom/localstorage/ActorsParent.cpp#l8113
We have orElse there so we fallback to it, but then dom/localstorage/ActorsParent.cpp#995:NS_ERROR_FILE_IS_LOCKED fails.

Nightly has QM_OR_ELSE_WARN there (instead of regular orElse), so the first error should disappear completely in the analysis, but still, ideally these would be separate stacks. I now understand what you meant in comment 9.

Jens Stutte [:jstutte]

Reporter

Comment 14

•

4 years ago

Clients	Sessions	Hits	Anchor	Stack
1148	1268	1655	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1028:None
384	422	463	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1013:NS_ERROR_FILE_NOT_FOUND
43	55	63	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_NOT_FOUND
25	26	76	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1013:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST

Jens Stutte [:jstutte]

Reporter

Comment 15

•

4 years ago

Clients	Sessions	Hits	Anchor	Stack
107	136	178	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1033:None

Jens Stutte [:jstutte]

Reporter

Comment 16

•

4 years ago

It seems we can have both NS_ERROR_FILE_NOT_FOUND and NS_ERROR_FILE_TARGET_DOES_NOT_EXIST, and according to bug 1519200 we already wanted to unify these.

Probably the more worrying case here is None, which appears to mean that the content (magic cookie) of the file is corrupted.

Comment 17

•

4 years ago

Clients	Sessions	Hits	Anchor	Stack
98	139	190	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1033:None
37	46	54	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_NOT_FOUND

Jens Stutte [:jstutte]

Reporter

Comment 18

•

4 years ago

•

Edited

These should have been reported as warnings.
It seems there is a problem in the telemetry that makes us truncate the stack prematurely:

    {
        "submit_timeabs": 1618736374547,
        "session_start_time": "2021-04-14T07:28:00",
        "submission_date": "2021-04-18",
        "build_id": "20210413093459",
        "client_id": "006320a7-7244-4cd6-8411-16df6b32b4a3",
        "session_id": "ab46e41b-83cc-4ca8-8c5b-0ceefa2e669f",
        "event_timestamp": 81601,
        "seq": 1,
        "context": "Initialization::TemporaryStorage",
        "source_file": "dom/localstorage/ActorsParent.cpp",
        "source_line": "1018",
        "severity": "ERROR",
        "result": "NS_ERROR_FILE_NOT_FOUND"
    },
    {
        "submit_timeabs": 1618385598076,
        "session_start_time": "2021-04-14T07:28:00",
        "submission_date": "2021-04-14",
        "build_id": "20210413093459",
        "client_id": "006320a7-7244-4cd6-8411-16df6b32b4a3",
        "session_id": "ab46e41b-83cc-4ca8-8c5b-0ceefa2e669f",
        "event_timestamp": 81663,
        "seq": 2,
        "context": "Initialization::TemporaryStorage",
        "source_file": "dom/localstorage/ActorsParent.cpp",
        "source_line": "8129",
        "severity": "WARNING",
        "result": "NS_ERROR_FILE_NOT_FOUND"
    },
    {
        "submit_timeabs": 1618736374547,
        "session_start_time": "2021-04-14T07:28:00",
        "submission_date": "2021-04-18",
        "build_id": "20210413093459",
        "client_id": "006320a7-7244-4cd6-8411-16df6b32b4a3",
        "session_id": "ab46e41b-83cc-4ca8-8c5b-0ceefa2e669f",
        "event_timestamp": 81663,
        "seq": 2,
        "context": "Initialization::TemporaryStorage",
        "source_file": "dom/localstorage/ActorsParent.cpp",
        "source_line": "8129",
        "severity": "WARNING",
        "result": "NS_ERROR_FILE_NOT_FOUND"
    },
    {
        "submit_timeabs": 1618684670837,
        "session_start_time": "2021-04-18T01:27:00",
        "submission_date": "2021-04-17",
        "build_id": "20210417095008",
        "client_id": "00665af5-d1ab-4543-a390-97678ddb681f",
        "session_id": "ab9b661b-351c-4662-9fb3-68abd78706b3",
        "event_timestamp": 11826,
        "seq": 1,
        "context": "Initialization::TemporaryStorage",
        "source_file": "dom/quota/ActorsParent.cpp",
        "source_line": "4115",
        "severity": "ERROR",
        "result": null
    },

Jens Stutte [:jstutte]

Reporter

Updated

•

4 years ago

Depends on: 1706928

Jens Stutte [:jstutte]

Reporter

Comment 19

•

4 years ago

And another stack seems to have a surprisingly long delay of 500ms between two frames which makes it become a split point:

    {
        "submit_timeabs": 1618459124058,
        "session_start_time": "2021-04-15T00:30:00",
        "submission_date": "2021-04-15",
        "build_id": "20210414093129",
        "client_id": "fe9dfac9-7194-494f-b48f-58aa477b87a9",
        "session_id": "4b80943e-6222-4b0c-9c10-eee3a3adf19e",
        "event_timestamp": 1283595,
        "seq": 1,
        "context": "Initialization::TemporaryStorage",
        "source_file": "dom/localstorage/ActorsParent.cpp",
        "source_line": "1033",
        "severity": "ERROR",
        "result": null
    },
    {
        "submit_timeabs": 1618459124058,
        "session_start_time": "2021-04-15T00:30:00",
        "submission_date": "2021-04-15",
        "build_id": "20210414093129",
        "client_id": "fe9dfac9-7194-494f-b48f-58aa477b87a9",
        "session_id": "4b80943e-6222-4b0c-9c10-eee3a3adf19e",
        "event_timestamp": 1284095,
        "seq": 2,
        "context": "Initialization::TemporaryStorage",
        "source_file": "dom/localstorage/ActorsParent.cpp",
        "source_line": "8129",
        "severity": "WARNING",
        "result": "NS_ERROR_FILE_CORRUPTED"
    },

Jens Stutte [:jstutte]

Reporter

Comment 20

•

4 years ago

Ignoring double events and increasing the maximum delay yields only warnings:

Warning stacks:

Clients	Sessions	Hits	Anchor	Stack
137	178	230	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1033:None <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_CORRUPTED
107	135	191	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1033:None <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_CORRUPTED
103	140	185	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1033:None <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_CORRUPTED
98	139	190	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1033:None <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_CORRUPTED
92	126	162	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1033:None <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_CORRUPTED
83	115	133	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1033:None <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_CORRUPTED
81	121	153	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1033:None <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_CORRUPTED
73	103	139	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1033:None <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_CORRUPTED
56	69	100	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1033:None <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_CORRUPTED
49	63	88	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_NOT_FOUND <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_NOT_FOUND
48	70	94	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1033:None <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_CORRUPTED
46	65	102	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1033:None <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_CORRUPTED
42	52	64	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_NOT_FOUND <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_NOT_FOUND
37	46	53	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_NOT_FOUND <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_NOT_FOUND
37	52	69	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_NOT_FOUND <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_NOT_FOUND
37	47	50	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_NOT_FOUND <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_NOT_FOUND
34	43	81	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_NOT_FOUND <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_NOT_FOUND
31	39	50	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1033:None <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_CORRUPTED
29	51	64	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_NOT_FOUND <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_NOT_FOUND
29	43	91	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_NOT_FOUND <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_NOT_FOUND
22	29	34	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1033:None <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_CORRUPTED
21	30	34	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_NOT_FOUND <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_NOT_FOUND
14	16	26	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_NOT_FOUND <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_NOT_FOUND
13	17	29	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_NOT_FOUND <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_NOT_FOUND
12	12	75	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_NOT_FOUND <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_NOT_FOUND
11	14	18	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1033:None <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_CORRUPTED
11	14	18	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1033:None <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_CORRUPTED
11	12	15	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1033:None <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_CORRUPTED
11	16	52	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST
10	11	11	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_NOT_FOUND <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_NOT_FOUND
9	10	10	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST
8	9	9	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST
8	9	9	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_NOT_FOUND <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_NOT_FOUND
7	9	9	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST
6	9	46	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST
6	7	53	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST
6	7	11	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1033:None <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_CORRUPTED
6	8	41	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST
6	7	16	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST
5	5	6	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_NOT_FOUND <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_NOT_FOUND
5	6	6	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST
5	7	9	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1033:None <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_CORRUPTED
5	8	21	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST
5	6	11	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1033:None <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_CORRUPTED
5	9	10	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST
4	9	17	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST
3	3	3	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_NOT_FOUND <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_NOT_FOUND
2	3	4	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_NOT_FOUND <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_NOT_FOUND
2	2	2	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST
2	2	2	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST
2	2	19	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST
2	4	4	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_NOT_FOUND <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_NOT_FOUND
1	1	2	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_NOT_FOUND <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_NOT_FOUND
1	1	297	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1022:NS_ERROR_FILE_IS_LOCKED <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_IS_LOCKED
1	1	1	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST
1	1	1	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST
1	1	2	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1020:None <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_CORRUPTED
1	1	1	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1018:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_TARGET_DOES_NOT_EXIST
1	1	1	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1022:NS_ERROR_FILE_IS_LOCKED <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_IS_LOCKED

Jan Varga [:janv]

Comment 21

•

4 years ago

Nice!

Jens Stutte [:jstutte]

Reporter

Comment 22

•

4 years ago

Given the quite frequent NS_ERROR_FILE_CORRUPTEDwe might want to consider flushing the usage file right after update?

Flags: needinfo?(jvarga)

Jan Varga [:janv]

Comment 23

•

4 years ago

Yeah, and if it works ok, we can do the same with the padding file for DOM cache and also the metadata file for origin directories.
The question is how to to do the flushing, fsync is probably the slowest option.

Flags: needinfo?(jvarga)

Andrew Sutherland [:asuth] (he/him)

Comment 24

•

4 years ago

nsFileStreamBase::Flush calls PR_Sync(mFD) (and which is called by nsSafeFileOutputStream::Flush which I would assume corresponds to fsync(fd) which explicitly knows the file that is being dealt with so it's not the same as us requesting that the entire filesystem be fsynced.

Alternately, we could switch to using something like NS_NewSafeLocalFileOutputStream, but that combines 1) calling Flush() and 2) use of nsIFile::createUnique to write to a different temporary file and then move the file into place. The moving the file into place is handy, but it looks a bit like the impl would end up picking a temporary file name of "usage-1" in the same directory which would complicate our directory scanning logic. We could of course do the file moving thing ourselves, possibly just be writing to "usage-journal" initially, then flush that and move that. (This might better be done by having a variant of the atomic/safe files that take a specific temporary file name to use instead of using createUnique?)

The general docs around this are:

https://searchfox.org/mozilla-central/source/xpcom/io/nsISafeOutputStream.idl
nsAtomicFileOutputStream "A safe file output stream that overwrites the destination file only once writing is complete. This protects against incomplete writes due to the process or the thread being interrupted or crashed."
nsSafeFileOutputStream "A safe file output stream that overwrites the destination file only once writing + flushing is complete. This protects against more classes of software/hardware errors than nsAtomicFileOutputStream, at the expense of being more costly to the disk, OS and battery."

Jens Stutte [:jstutte]

Reporter

Comment 25

•

3 years ago

Clients	Sessions	Hits	Anchor	Stack
9070	11746	14653	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1033:None
3	4	13	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1020:None

Clients	Sessions	Hits	Anchor	Stack
6072	7473	9742	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1033:None
2	2	2	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1020:None

Jan Varga [:janv]

Comment 26

•

3 years ago

It seems there's again a problem with split points, the errors from comment 25 should be in the warning stacks.

Jens Stutte [:jstutte]

Reporter

Comment 27

•

3 years ago

(In reply to Jan Varga [:janv] from comment #26)

It seems there's again a problem with split points, the errors from comment 25 should be in the warning stacks.

Yes, it is max-delta guessing:

    {
        "submit_timeabs": 1619448927403,
        "session_start_time": "2021-04-26T13:21:00",
        "submission_date": "2021-04-26",
        "build_id": "20210422190146",
        "client_id": "d3c7414c-6d28-4783-bfef-c73512769b99",
        "session_id": "c00b85f0-db5c-4577-9b4b-3a097f933ce9",
        "event_timestamp": 1975924,
        "seq": 1,
        "context": "Initialization::TemporaryStorage",
        "source_file": "dom/localstorage/ActorsParent.cpp",
        "source_line": "1033",
        "severity": "ERROR",
        "result": null
    },
    {
        "submit_timeabs": 1619448927403,
        "session_start_time": "2021-04-26T13:21:00",
        "submission_date": "2021-04-26",
        "build_id": "20210422190146",
        "client_id": "d3c7414c-6d28-4783-bfef-c73512769b99",
        "session_id": "c00b85f0-db5c-4577-9b4b-3a097f933ce9",
        "event_timestamp": 1976782,
        "seq": 2,
        "context": "Initialization::TemporaryStorage",
        "source_file": "dom/localstorage/ActorsParent.cpp",
        "source_line": "8129",
        "severity": "WARNING",
        "result": "NS_ERROR_FILE_CORRUPTED"
    },

becomes 858ms, and we split over 800ms delta. I assume there is no real good solution against those slow outliers. I could only imagine to collect all deltas for equal frames first and build the average or such.

Jens Stutte [:jstutte]

Reporter

Comment 28

•

3 years ago

•

Edited

(In reply to Jens Stutte [:jstutte] from comment #27)

I could only imagine to collect all deltas for equal frames first and build the average or such.

With that modification we get those stacks as warnings again (example):

Clients	Sessions	Hits	Anchor	Stack
9070	11746	14653	dom/localstorage/ActorsParent.cpp:LoadUsageFile	dom/localstorage/ActorsParent.cpp#1033:None <- dom/localstorage/ActorsParent.cpp#8129:NS_ERROR_FILE_CORRUPTED

Jan Varga [:janv]

Comment 29

•

3 years ago

Thanks!

Jens Stutte [:jstutte]

Reporter

Updated

•

3 years ago

Blocks: 1708119

Jens Stutte [:jstutte]

Reporter

Updated

•

3 years ago

No longer blocks: 1708119

Updated

•

3 years ago

Status: NEW → RESOLVED

Closed: 3 years ago

Resolution: --- → FIXED