Closed Bug 892606 Opened 10 years ago Closed 10 years ago

Intermittent test_keycodes.xul | Exited with code -1073741819 during test run | application crashed [@ mozilla::widget::VirtualKey::GetNativeUniChars(unsigned char)]

Categories

(Core :: Widget, defect)

Product:
Core
Component:
Widget
Platform:
x86
Windows 8
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla26
Tracking Flags:
Tracking Status
firefox24 --- unaffected
firefox25 + fixed
firefox26 + fixed

People

(Reporter: RyanVM, Assigned: masayuki)

Details

(Keywords: crash, intermittent-failure, regression)

Attachments

(4 files)

part.1 Add debug logs to KeyboardLayout.cpp
3.99 KB, patch
jimm
: review+
Details | Diff | Splinter Review
part.2 Fix scancode value in lParam generated by KeyboardLayout::SynthesizeNativeKeyEvent()
2.90 KB, patch
jimm
: review+
Details | Diff | Splinter Review
part.3 FakeCharMsg should be marked as consumed and only non-consumed char message should be synthesized
14.02 KB, patch
jimm
: review+
Details | Diff | Splinter Review
part.4 Don't handle non-keydown message as a part of dead key handling after keydown causes resetting dead key state
3.63 KB, patch
jimm
: review+
Details | Diff | Splinter Review 
Masayuki, I can't help but notice that this happened on the push for bug 875674. Is it possible that this was caused by that?

https://tbpl.mozilla.org/php/getParsedLog.php?id=25162872&tree=Mozilla-Inbound

WINNT 6.2 mozilla-inbound debug test mochitest-other on 2013-07-11 02:17:04 PDT for push 86a041d63d65
slave: t-w864-ix-054

02:38:36     INFO -  50909 INFO TEST-PASS | chrome://mochitests/content/chrome/widget/tests/test_keycodes.xul | French keyCode=221 (0xDD) chars='', wrong keycode
02:38:36     INFO -  50910 INFO TEST-PASS | chrome://mochitests/content/chrome/widget/tests/test_keycodes.xul | French keyCode=221 (0xDD) chars='', wrong location
02:38:36     INFO -  50911 INFO TEST-PASS | chrome://mochitests/content/chrome/widget/tests/test_keycodes.xul | keycode is undefined
02:38:36     INFO -  [Parent 2960] WARNING: Unknown key code comes, please check latest MSDN document, there may be some new keycodes we have not known.: file e:/builds/moz2_slave/m-in-w32-d-0000000000000000000/build/widget/windows/KeyboardLayout.cpp, line 2057
02:38:37     INFO -  WARNING: shutting down early because of crash!: file e:/builds/moz2_slave/m-in-w32-d-0000000000000000000/build/dom/plugins/ipc/PluginModuleChild.cpp, line 703
02:38:37     INFO -  WARNING: plugin process _exit()ing: file e:/builds/moz2_slave/m-in-w32-d-0000000000000000000/build/dom/plugins/ipc/PluginModuleChild.cpp, line 668
02:38:37     INFO -  NPP_Destroy
02:38:37     INFO -  NPP_Destroy
02:38:37     INFO -  nsStringStats
02:38:37     INFO -   => mAllocCount:             98
02:38:37     INFO -   => mReallocCount:            1
02:38:37     INFO -   => mFreeCount:              17  --  LEAKED 81 !!!
02:38:37     INFO -   => mShareCount:            153
02:38:37     INFO -   => mAdoptCount:              0
02:38:37     INFO -   => mAdoptFreeCount:          0
02:38:37  WARNING -  TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/widget/tests/test_keycodes.xul | Exited with code -1073741819 during test run
02:38:37     INFO -  INFO | automation.py | Application ran for: 0:18:30.535000
02:38:37     INFO -  INFO | zombiecheck | Reading PID log: c:\users\cltbld~1.t-w\appdata\local\temp\tmpddp1papidlog
02:38:37     INFO -  ==> process 2960 launched child process 1784 ("C:\slave\test\build\application\firefox\plugin-container.exe" --channel=2960.1308d540.1038908931 "c:\users\cltbld~1.t-w\appdata\local\temp\tmpoc2j1m\plugins\nptest.dll" -greomni "C:\slave\test\build\application\firefox\omni.ja" -appomni "C:\slave\test\build\application\firefox\browser\omni.ja" -appdir "C:\slave\test\build\application\firefox\browser" - 2960 "\\.\pipe\gecko-crash-server-pipe.2960" plugin)
02:38:37     INFO -  ==> process 2960 launched child process 2312 ("C:\slave\test\build\application\firefox\plugin-container.exe" --channel=2960.15f10bf0.1437780737 -greomni "C:\slave\test\build\application\firefox\omni.ja" -appomni "C:\slave\test\build\application\firefox\browser\omni.ja" -appdir "C:\slave\test\build\application\firefox\browser" - 2960 "\\.\pipe\gecko-crash-server-pipe.2960" tab)
02:38:37     INFO -  ==> process 2960 launched child process 2296 ("C:\slave\test\build\application\firefox\plugin-container.exe" --channel=2960.15ffd240.1498367386 "c:\users\cltbld~1.t-w\appdata\local\temp\tmpoc2j1m\plugins\nptest.dll" -greomni "C:\slave\test\build\application\firefox\omni.ja" -appomni "C:\slave\test\build\application\firefox\browser\omni.ja" -appdir "C:\slave\test\build\application\firefox\browser" - 2960 "\\.\pipe\gecko-crash-server-pipe.2960" plugin)
02:38:37     INFO -  ==> process 2960 launched child process 3940 ("C:\slave\test\build\application\firefox\plugin-container.exe" --channel=2960.15ffc4d0.1927607691 "c:\users\cltbld~1.t-w\appdata\local\temp\tmpoc2j1m\plugins\nptest.dll" -greomni "C:\slave\test\build\application\firefox\omni.ja" -appomni "C:\slave\test\build\application\firefox\browser\omni.ja" -appdir "C:\slave\test\build\application\firefox\browser" - 2960 "\\.\pipe\gecko-crash-server-pipe.2960" plugin)
02:38:37     INFO -  ==> process 2960 launched child process 3748 ("C:\slave\test\build\application\firefox\plugin-container.exe" --channel=2960.15fffa90.1215232263 "c:\users\cltbld~1.t-w\appdata\local\temp\tmpoc2j1m\plugins\nptest.dll" -greomni "C:\slave\test\build\application\firefox\omni.ja" -appomni "C:\slave\test\build\application\firefox\browser\omni.ja" -appdir "C:\slave\test\build\application\firefox\browser" - 2960 "\\.\pipe\gecko-crash-server-pipe.2960" plugin)
02:38:37     INFO -  ==> process 2960 launched child process 3104 ("C:\slave\test\build\application\firefox\plugin-container.exe" --channel=2960.160002a0.1461066567 "c:\users\cltbld~1.t-w\appdata\local\temp\tmpoc2j1m\plugins\nptest.dll" -greomni "C:\slave\test\build\application\firefox\omni.ja" -appomni "C:\slave\test\build\application\firefox\browser\omni.ja" -appdir "C:\slave\test\build\application\firefox\browser" - 2960 "\\.\pipe\gecko-crash-server-pipe.2960" plugin)
02:38:37     INFO -  ==> process 2960 launched child process 2988 ("C:\slave\test\build\application\firefox\plugin-container.exe" --channel=2960.15ffaf50.1932189351 "c:\users\cltbld~1.t-w\appdata\local\temp\tmpoc2j1m\plugins\nptest.dll" -greomni "C:\slave\test\build\application\firefox\omni.ja" -appomni "C:\slave\test\build\application\firefox\browser\omni.ja" -appdir "C:\slave\test\build\application\firefox\browser" - 2960 "\\.\pipe\gecko-crash-server-pipe.2960" plugin)
02:38:37     INFO -  ==> process 2960 launched child process 2224 ("C:\slave\test\build\application\firefox\plugin-container.exe" --channel=2960.16001d80.1564711947 "c:\users\cltbld~1.t-w\appdata\local\temp\tmpoc2j1m\plugins\nptest.dll" -greomni "C:\slave\test\build\application\firefox\omni.ja" -appomni "C:\slave\test\build\application\firefox\browser\omni.ja" -appdir "C:\slave\test\build\application\firefox\browser" - 2960 "\\.\pipe\gecko-crash-server-pipe.2960" plugin)
02:38:37     INFO -  ==> process 2960 launched child process 1320 ("C:\slave\test\build\application\firefox\plugin-container.exe" --channel=2960.16001ed8.2137159064 "c:\users\cltbld~1.t-w\appdata\local\temp\tmpoc2j1m\plugins\nptest.dll" -greomni "C:\slave\test\build\application\firefox\omni.ja" -appomni "C:\slave\test\build\application\firefox\browser\omni.ja" -appdir "C:\slave\test\build\application\firefox\browser" - 2960 "\\.\pipe\gecko-crash-server-pipe.2960" plugin)
02:38:37     INFO -  ==> process 2960 launched child process 836 ("C:\slave\test\build\application\firefox\plugin-container.exe" --channel=2960.2098c160.900661566 "c:\users\cltbld~1.t-w\appdata\local\temp\tmpoc2j1m\plugins\nptest.dll" -greomni "C:\slave\test\build\application\firefox\omni.ja" -appomni "C:\slave\test\build\application\firefox\browser\omni.ja" -appdir "C:\slave\test\build\application\firefox\browser" - 2960 "\\.\pipe\gecko-crash-server-pipe.2960" plugin)
02:38:43  WARNING -  PROCESS-CRASH | chrome://mochitests/content/chrome/widget/tests/test_keycodes.xul | application crashed [@ mozilla::widget::VirtualKey::GetNativeUniChars(unsigned char)]
02:38:43     INFO -  Crash dump filename: c:\users\cltbld~1.t-w\appdata\local\temp\tmpoc2j1m\minidumps\601afb09-1273-42e2-9e0d-b17667a0b0a8.dmp
02:38:43     INFO -  Operating system: Windows NT
02:38:43     INFO -                    6.2.9200
02:38:43     INFO -  CPU: x86
02:38:43     INFO -       GenuineIntel family 6 model 30 stepping 5
02:38:43     INFO -       8 CPUs
02:38:43     INFO -  Crash reason:  EXCEPTION_ACCESS_VIOLATION_READ
02:38:43     INFO -  Crash address: 0x59f6fa8
02:38:43     INFO -  Thread 0 (crashed)
02:38:43     INFO -   0  xul.dll!mozilla::widget::VirtualKey::GetNativeUniChars(unsigned char) [KeyboardLayout.cpp:86a041d63d65 : 341 + 0x0]
02:38:43     INFO -      eip = 0x734b50ff   esp = 0x00a8c870   ebp = 0x00a8c87c   ebx = 0x00000000
02:38:43     INFO -      esi = 0x059f6fa8   edi = 0x00a8c8fc   eax = 0x0000040c   ecx = 0x00000000
02:38:43     INFO -      edx = 0x00000001   efl = 0x00210246
02:38:43     INFO -      Found by: given as instruction pointer in context
02:38:43     INFO -   1  xul.dll!mozilla::widget::VirtualKey::GetUniChars(unsigned char) [KeyboardLayout.cpp:86a041d63d65 : 316 + 0x7]
02:38:43     INFO -      eip = 0x734b5db4   esp = 0x00a8c884   ebp = 0x00a8c8d4
02:38:43     INFO -      Found by: call frame info
02:38:43     INFO -   2  xul.dll!mozilla::widget::KeyboardLayout::InitNativeKey(mozilla::widget::NativeKey &,mozilla::widget::ModifierKeyState const &) [KeyboardLayout.cpp:86a041d63d65 : 1491 + 0x28]
02:38:43     INFO -      eip = 0x734b699d   esp = 0x00a8c8dc   ebp = 0x00a8c978
02:38:43     INFO -      Found by: call frame info
02:38:43     INFO -   3  xul.dll!mozilla::widget::NativeKey::NativeKey(nsWindowBase *,tagMSG const &,mozilla::widget::ModifierKeyState const &,mozilla::widget::NativeKey::FakeCharMsg const *) [KeyboardLayout.cpp:86a041d63d65 : 564 + 0xf]
02:38:43     INFO -      eip = 0x734b7178   esp = 0x00a8c980   ebp = 0x00a8c9ac
02:38:43     INFO -      Found by: call frame info
02:38:43     INFO -   4  xul.dll!mozilla::widget::KeyboardLayout::SynthesizeNativeKeyEvent(nsWindowBase *,int,int,unsigned int,nsAString_internal const &,nsAString_internal const &) [KeyboardLayout.cpp:86a041d63d65 : 2313 + 0x1c]
02:38:43     INFO -      eip = 0x734b88bf   esp = 0x00a8c9b4   ebp = 0x00a8ced0
02:38:43     INFO -      Found by: call frame info
02:38:43     INFO -   5  xul.dll!nsWindow::SynthesizeNativeKeyEvent(int,int,unsigned int,nsAString_internal const &,nsAString_internal const &) [nsWindow.cpp:86a041d63d65 : 5655 + 0x16]
02:38:43     INFO -      eip = 0x734e18d9   esp = 0x00a8ced8   ebp = 0x00a8cef4
02:38:43     INFO -      Found by: call frame info
02:38:43     INFO -   6  xul.dll!nsDOMWindowUtils::SendNativeKeyEvent(int,int,int,nsAString_internal const &,nsAString_internal const &) [nsDOMWindowUtils.cpp:86a041d63d65 : 1031 + 0x20]
02:38:43     INFO -      eip = 0x72dee71f   esp = 0x00a8cefc   ebp = 0x00a8cf18
02:38:43     INFO -      Found by: call frame info
02:38:43     INFO -   7  xul.dll!NS_InvokeByIndex [xptcinvoke.cpp:86a041d63d65 : 70 + 0x2]
02:38:43     INFO -      eip = 0x7262f12f   esp = 0x00a8cf20   ebp = 0x00a8cf4c
02:38:43     INFO -      Found by: call frame info
(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #0)
> Masayuki, I can't help but notice that this happened on the push for bug
> 875674. Is it possible that this was caused by that?

I don't think so. The bug changes Mac's code and few XP code. However, the changed XP code isn't used on Windows in default settings.

> chrome://mochitests/content/chrome/widget/tests/test_keycodes.xul | French
> keyCode=221 (0xDD) chars='', wrong location
> 02:38:36     INFO -  50911 INFO TEST-PASS |
> chrome://mochitests/content/chrome/widget/tests/test_keycodes.xul | keycode
> is undefined
> 02:38:36     INFO -  [Parent 2960] WARNING: Unknown key code comes, please
> check latest MSDN document, there may be some new keycodes we have not
> known.

This warning is very strange. It's crashed at this test:
http://mxr.mozilla.org/mozilla-central/source/widget/tests/test_keycodes.xul#1954

So, the sending virtual keycode is same as its previous test but the previous test passed without this warning. Additionally, this warning happens only when the virtual keycode value is not defined. And even if the value is broken,

http://mxr.mozilla.org/mozilla-central/source/widget/windows/KeyboardLayout.cpp#1459

The virtualKeyIndex must be -1.

Then, this crash must not happen. However, it happens. Therefore, it might be the memory was already broken...
We're still hitting this pretty regularly. Any ideas?
Flags: needinfo?(masayuki)
No, I don't.

There are some crash reports:
https://crash-stats.mozilla.com/report/list?product=Firefox&query_search=signature&query_type=contains&reason_type=contains&date=2013-08-06&range_value=28&range_unit=days&hang_type=any&process_type=any&signature=mozilla%3A%3Awidget%3A%3AVirtualKey%3A%3AGetNativeUniChars%28unsigned+char%29

I'll take a look as far as possible. However, I'll be offline next week. So, if I cannot touch this bug this week, I'll do it 8/19 or later.

And the reported stacks are very odd... That's impossible...
Flags: needinfo?(masayuki)
Perhaps, I found the cause.
Assignee: nobody → masayuki
Status: NEW → ASSIGNED
First, logging better information for debug.

Then, we know what happens at crash. Immediately before the crash, we can see following log twice:

activeDeadKeyIndex: -1
mActiveDeadKey: 0xFFFFFFFF (-1)
virtualKey: 0xDD

That means we access mVirtualKeys[-1] at WM_CHAR for second character (The second character of "^^") and WM_KEYUP because mActiveDeadKey was already cleared as -1 at handling WM_KEYDOWN.
Attachment #788186 - Flags: review?(jmathies)
This patch doesn't fix this bug directly. However, this causes synthesizing wrong WM_CHAR message. Then, NativeKey fails to compute correct virtual keycode value and DOM keyCode value.

1. Use current synthesizing key in the for loop (the first chunk and second chunk).
2. The scancode should be stored at 23-16 bit of lParam (the last chunk).
Attachment #788188 - Flags: review?(jmathies)
Next, let's improve the SynthesizeNativeKey(). Currently, it assumes that second or later WM_CHAR messages are not consumed. Therefore, 2nd or later characters are sent with HandleCharMessage().

However, HandleKeyDownMessage() may consume two or more WM_CHAR messages. So, let's send all following WM_CHAR messages to HandleKeyDownMessage(). And then, if it's consumed, mark it as so. Finally, only non-consumed char messages should be sent to HandleCharMessage().
Attachment #788191 - Flags: review?(jmathies)
This is the fixing patch of this crash bug.

First, the NeedsToHandleWithoutFollowingCharMsg() checks mIsDeadKey for not firing keypress events case. However, this is wrong. mIsDeadKey is true when the dead key causes text input such as 2nd same key press. So, it should check whether the inputting text is empty or not.

Next, at second key press of same dead key, WM_KEYDOWN causes resetting the dead key state (the bottom of the patch, a call of DeactivateDeadKeyState()). So, when following WM_CHAR (for second character) and WM_KEYUP handler creates NativeKey instance, the dead key handling is already finished (at the WM_KEYDOWN). Therefore, if mActiveDeadKey is already cleared, let's set only the last character which is inputted by the last pressed key.

Then, we can avoid to reach here:
>     UniCharsAndModifiers prevDeadChars =
>       mVirtualKeys[activeDeadKeyIndex].GetUniChars(mDeadKeyShiftState);

In the future, the keyup event's KeyboardEvent.key will have only the last character by this change. However, I believe that this is right behavior. Because WM_KEYUP may not be received immediately after the second dead key press. E.g., if user keeps pressing the key, auto repeat causes next WM_KEYDOWN. Or user might press another dead key before releasing the pressed dead key. So, it's impossible to compute the actual inputted text for WM_KEYUP event in such complex path.

This patch only changes the normal path (i.e., not only for the test path).
Attachment #788193 - Flags: review?(jmathies)
https://tbpl.mozilla.org/?tree=Try&usebuildbot=1&rev=c53ce5c66a64

I don't see the out-of-range warning. And actually all tests are not crashed.
I think that this is NOT a regression of 25 due to the code is older than it.

However, according to the crash reports, this crash starts 25. So, I think that this should be back ported to only 25.

https://crash-stats.mozilla.com/report/list?product=Firefox&query_search=signature&query_type=contains&reason_type=contains&date=2013-08-06&range_value=28&range_unit=days&hang_type=any&process_type=any&signature=mozilla%3A%3Awidget%3A%3AVirtualKey%3A%3AGetNativeUniChars%28unsigned+char%29

The STR of this bug is:

1. Type a dead key
2. Type a dead key again

Then, the second key press handle may cause crash due to accessing out of range of an array.
status-firefox25: --- → affected
status-firefox26: --- → affected
tracking-firefox25: --- → ?
tracking-firefox26: --- → ?
s/the second key press handle/the second key press handler
Attachment #788186 - Flags: review?(jmathies) → review+
Comment on attachment 788188 [details] [diff] [review]
part.2 Fix scancode value in lParam generated by KeyboardLayout::SynthesizeNativeKeyEvent()

Review of attachment 788188 [details] [diff] [review]:
-----------------------------------------------------------------

::: widget/windows/KeyboardLayout.h
@@ +303,5 @@
>        MSG msg;
>        msg.hwnd = aWnd;
>        msg.message = mIsDeadKey ? WM_DEADCHAR : WM_CHAR;
>        msg.wParam = static_cast<WPARAM>(mCharCode);
> +      msg.lParam = static_cast<LPARAM>(mScanCode << 16);

Where are we getting mScanCode from, WinUtils::GetScanCode?
Attachment #788188 - Flags: review?(jmathies) → review+
Comment on attachment 788191 [details] [diff] [review]
part.3 FakeCharMsg should be marked as consumed and only non-consumed char message should be synthesized

Review of attachment 788191 [details] [diff] [review]:
-----------------------------------------------------------------

::: widget/windows/KeyboardLayout.cpp
@@ +2314,5 @@
>          NativeKey nativeKey(aWidget, keyDownMsg, modKeyState);
>          nativeKey.HandleKeyDownMessage();
>        } else {
> +        nsAutoTArray<NativeKey::FakeCharMsg, 10> fakeCharMsgs;
> +        for (uint32_t j = 0; j < chars.Length(); j++) {

nit - not a huge fan of index variables in small loops like this named 'i' or 'j', I'd prefer something like 'idx'.
Attachment #788191 - Flags: review?(jmathies) → review+
Attachment #788193 - Flags: review?(jmathies) → review+
(In reply to Jim Mathies [:jimm] from comment #26)
> Comment on attachment 788188 [details] [diff] [review]
> part.2 Fix scancode value in lParam generated by
> KeyboardLayout::SynthesizeNativeKeyEvent()
> 
> Review of attachment 788188 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: widget/windows/KeyboardLayout.h
> @@ +303,5 @@
> >        MSG msg;
> >        msg.hwnd = aWnd;
> >        msg.message = mIsDeadKey ? WM_DEADCHAR : WM_CHAR;
> >        msg.wParam = static_cast<WPARAM>(mCharCode);
> > +      msg.lParam = static_cast<LPARAM>(mScanCode << 16);
> 
> Where are we getting mScanCode from, WinUtils::GetScanCode?

Exactly.
(In reply to Jim Mathies [:jimm] from comment #27)
> Comment on attachment 788191 [details] [diff] [review]
> part.3 FakeCharMsg should be marked as consumed and only non-consumed char
> message should be synthesized
> 
> Review of attachment 788191 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: widget/windows/KeyboardLayout.cpp
> @@ +2314,5 @@
> >          NativeKey nativeKey(aWidget, keyDownMsg, modKeyState);
> >          nativeKey.HandleKeyDownMessage();
> >        } else {
> > +        nsAutoTArray<NativeKey::FakeCharMsg, 10> fakeCharMsgs;
> > +        for (uint32_t j = 0; j < chars.Length(); j++) {
> 
> nit - not a huge fan of index variables in small loops like this named 'i'
> or 'j', I'd prefer something like 'idx'.

Hmm, I don't like it... The loop is in a for loop which uses "i". So, "j" is better at least here...
I'd like to know jimm still thinks I should change the variable name even in this case (see comment 29).
Flags: needinfo?(jmathies)
(In reply to Masayuki Nakano (:masayuki) (Mozilla Japan) (offline: 8/13-8/18 JST) from comment #30)
> I'd like to know jimm still thinks I should change the variable name even in
> this case (see comment 29).

I usually try to avoid i's and j's in general, but it's not that big a deal. Your code, you can use the variables you like.
Flags: needinfo?(jmathies)
Can we uplift this to Aurora too please?
status-firefox26: affected → fixed
(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #34)
> Can we uplift this to Aurora too please?

Of course, but I think that we should wait next week for tested by Nightly users.
+1 to comment 35, but a=akeybl when ready to uplift.
tracking-firefox25: ? → +
tracking-firefox26: ? → +
Keywords: regression
You need to log in before you can comment on or make changes to this bug.