#2 Updated by intrigeri 2015-02-21 18:48:12

• Assignee set to kytv
• QA Check set to Info Needed

Did you try with -grab, as suggested in the last comment on this Debian bug report?

#3 Updated by kytv 2015-02-21 21:09:45

• Assignee deleted (kytv)

BitingBird wrote:
> Maybe answer upstream to let them know that the bug still occurs ? (last answer was 4 years ago…)

I will once I can formulate how to explain the issue in a useful way. :)

intrigeri wrote:
> Did you try with -grab, as suggested in the last comment on this Debian bug report?

I should have included this in the ticket, but I did and it didn’t help. With the test suite it had the effect of causing the boot to look as if hung at the initial qemu bootscreen, then the Tails bootsplash was displayed far later than what is normal.

 Background:                                                            # features/ssh.feature:8
    Given a computer                                                     # features/step_definitions/common_steps.rb:64
[log] CLICK on (1024,384)
    And I start the computer                                             # features/step_definitions/common_steps.rb:133
    And the computer boots Tails                                         # features/step_definitions/common_steps.rb:211
      FindFailed: can not find TailsBootSplash.png on the screen.
      Line ?, in File ? (RuntimeError)
      /usr/lib/ruby/vendor_ruby/cucumber/core_ext/instance_exec.rb:73:in `rescue in cucumber_run_with_backtrace_filtering'
      /usr/lib/ruby/vendor_ruby/cucumber/core_ext/instance_exec.rb:68:in `cucumber_run_with_backtrace_filtering'
      /usr/lib/ruby/vendor_ruby/cucumber/core_ext/instance_exec.rb:36:in `cucumber_instance_exec'
      /usr/lib/ruby/vendor_ruby/cucumber/rb_support/rb_step_definition.rb:97:in `invoke'
      /usr/lib/ruby/vendor_ruby/cucumber/step_match.rb:25:in `invoke'
      /usr/lib/ruby/vendor_ruby/cucumber/ast/step_invocation.rb:60:in `invoke'
      /usr/lib/ruby/vendor_ruby/cucumber/ast/step_invocation.rb:38:in `accept'
      /usr/lib/ruby/vendor_ruby/cucumber/ast/tree_walker.rb:106:in `block in visit_step'

There’s still more troubleshooting & experimentation to be done.

#4 Updated by intrigeri 2015-02-24 15:15:19

• Target version set to Tails_1.4
• Parent task set to Feature #8539

This often happens on isotester1.lizard, hence setting Feature #8539 as the parent, and the target version to 1.4 accordingly => kytv, anonym: we’ll need an assignee on this one.

#5 Updated by intrigeri 2015-02-24 15:16:21

• related to Bug #8140: Running applications via the GNOME menu is fragile added

#6 Updated by intrigeri 2015-02-24 15:16:30

• related to Bug #8875: Make running applications from the GNOME menu more robust, again added

#7 Updated by intrigeri 2015-02-24 15:17:05

• related to Feature #8947: Use the headless Ruby gem in the automated test suite added

#8 Updated by intrigeri 2015-02-24 15:17:22

• related to deleted (Feature #8947: Use the headless Ruby gem in the automated test suite)

#9 Updated by intrigeri 2015-02-24 15:20:33

• blocks #8538 added

#10 Updated by anonym 2015-03-03 22:08:28

• Assignee set to anonym
• Target version changed from Tails_1.4 to Tails_1.3.2

#11 Updated by intrigeri 2015-03-15 11:42:56

• QA Check deleted (Info Needed)

If we decide to go with hhpc, I guess we need a subtask titled “Switch from unclutter to hhpc in the test suite”, that should cover:

1. decide who’ll be maintaining that package in Debian
2. file an ITP bug in Debian
3. upload to Debian (and temporarily to our own APT repo, perhaps)
4. wait for the package to make it through NEW
5. either “wait” for Feature #8165 (and then install hhpc from sid on jessie-backports), or for the package to reach testing after the Jessie release (and then backport it into wheezy-sloppy-backports)

Alternatively, perhaps a cheaper solution on the long run would be to find out what unclutter does that breaks things for us, compare with the hhcp implementation, and try to make unclutter behave in a way that’s suitable for us (possibly with a command-line flag). This would avoid having to maintain one more package in Debian.

#12 Updated by anonym 2015-04-01 13:30:06

• Target version changed from Tails_1.3.2 to Tails_1.4

#13 Updated by anonym 2015-04-07 15:29:42

• File app_spam.feature added
• File <del>missing: I_start-fix.patch</del> added
• File I_start-fix-with-debugging.patch added
• Assignee changed from anonym to kytv
• QA Check set to Info Needed

At least in my experiments (in a nested VM setup) it doesn’t matter if I run with unclutter, hhpc or neither of them. The I start ... via the GNOME ... applications menu steps fail occasionally no matter what. This doesn’t rule out that e.g. unclutter makes the situation worse, but something else seems to be involved too.

I’ve observed that the frequency of failures increases when --capture:ing the sessions (which I think intrigeri has observed too(?)) so I investigated it further by frying the CPU with one cat /dev/urandom > /dev/null instance per virtual core inside the guest running the test suite. That make the error trigger almost all the time. For each of those processes I killed, I could notice that the error rate dropped.

I’ve carefully reviewed captured sessions, looking at how the GNOME applications menu errors manifest, and made the following observations:

1. Clicking on the Applications button to make the menu appear never fails.

1. Clicking on the entry for the final application (so it starts) never fails.

1. When opening a submenu, sometimes another submenu (1-2 steps below) opens => failure.

1. When opening a submenu, sometimes it opens and closes immediately => failure.

1. When opening a submenu, sometimes no menu at all is opened => failure.

First I was thinking that perhaps it’s a bug in virt-viewer (or something else on the tester system, like the xorg/@xvfb@ stack?) so mouse events are dropped or mismanaged (e.g. a click happens at the wrong coordinates) under heavy load. However, that wouldn’t explain why 1 and 2 above never fails. Rather, it seems that GNOME’s submenu opening is buggy under heavy load.

A workaround can be found in I_start-fix.patch and it works even most of the time when I’m burning the CPU excessively while running the test suite, and I never saw it fail under more realistic loads (even with --caputre). I_start-fix-with-debugging.patch is the same fix, but with more debug logging, which helped me see that the error frequency would have more or less the same without this fix. I’ve also attached the .feature I was testing this with.

kytv, could you please try to reproduce this and do some more testing w.r.t. if unclutter or hhpc actually have anything to do with the problem? I.e. for x in unclutter, hhpc, “neither unclutter nor hhpc”, run the test suite with x on app_spam.feature and check:

• without any of my patches

that heavy CPU load triggers the error often

that normal CPU load never triggers the error occasionally

• with I_start-fix.patch

that heavy CPU load triggers the error occasionally

that normal CPU load never triggers the error

• with I_start-fix-with-debugging.patch

that normal CPU load never triggers the error but that the number of errors it caught and fixed are about the same as without the fix (under normal load)

Here, “often”, “occasionally” and “never” are vague, but if you get results similar to mine, it shouldn’t be an issue. For “heavy CPU load” I did for x in $(seq $(nproc)); do cat /dev/urandom > /dev/null; done but I was without an Internet connection and couldn’t install e.g. the cpuburn package, which probably is easier.

And yes, this means running 3*5*150 = 2250 scenarios… :)

#14 Updated by anonym 2015-04-07 22:53:36

• File deleted (I_start-fix.patch)

#15 Updated by anonym 2015-04-07 22:55:21

• File <del>missing: I_start-fix.patch</del> added

The previous patch was an old, bugged version.

#16 Updated by kytv 2015-04-11 10:07:07

• Assignee changed from kytv to anonym

anonym wrote:
> The previous patch was an old, bugged version.

The current I_start_fix.patch fails consistently without load.

  Scenario: start Gedit (1 submenu)                                      # features/app_spam.feature:13
    When I start "Gedit" via the GNOME "Accessories" applications menu   # features/step_definitions/common_steps.rb:782
      execution expired (Timeout::Error)
      ./features/support/helpers/sikuli_helper.rb:120:in `new'
      ./features/support/helpers/sikuli_helper.rb:120:in `method_missing'
      ./features/support/helpers/sikuli_helper.rb:120:in `wait_and_click'
      ./features/step_definitions/common_steps.rb:777:in `block in gnome_app_menu_click_helper'
      ./features/support/helpers/misc_helpers.rb:25:in `block (2 levels) in try_for'
      ./features/support/helpers/misc_helpers.rb:23:in `loop'
      ./features/support/helpers/misc_helpers.rb:23:in `block in try_for'
      ./features/support/helpers/misc_helpers.rb:22:in `try_for'
      ./features/step_definitions/common_steps.rb:775:in `gnome_app_menu_click_helper'
      ./features/step_definitions/common_steps.rb:795:in `/^I start "([^"]+)" via the GNOME "([^"]+)" applications menu$/'
      features/app_spam.feature:14:in `When I start "Gedit" via the GNOME "Accessories" applications menu'
    Then I see "GeditWindow.png" after at most 10 seconds                # features/step_definitions/common_steps.rb:413
Scenario failed at time 00:02:24
Took screenshot "/tmp/TailsToaster/app_spam-2015-04-11T10:02:48+00:00.png"

  Scenario: start Seahorse (2 submenus)                                            # features/app_spam.feature:17

(virt-viewer:5818): Gdk-CRITICAL **: gdk_window_set_cursor: assertion 'GDK_IS_WINDOW (window)' failed
    When I start "Seahorse" via the GNOME "System"/"Preferences" applications menu # features/step_definitions/common_steps.rb:798
      execution expired (Timeout::Error)
      ./features/support/helpers/misc_helpers.rb:37:in `sleep'
      ./features/support/helpers/misc_helpers.rb:37:in `block (2 levels) in try_for'
      ./features/support/helpers/misc_helpers.rb:23:in `loop'
      ./features/support/helpers/misc_helpers.rb:23:in `block in try_for'
      ./features/support/helpers/misc_helpers.rb:22:in `try_for'
      ./features/step_definitions/common_steps.rb:775:in `gnome_app_menu_click_helper'
      ./features/step_definitions/common_steps.rb:813:in `/^I start "([^"]+)" via the GNOME "([^"]+)"\/"([^"]+)" applications menu$/'
      features/app_spam.feature:18:in `When I start "Seahorse" via the GNOME "System"/"Preferences" applications menu'
    Then I see "SeahorseWindow.png" after at most 10 seconds                       # features/step_definitions/common_steps.rb:413
Scenario failed at time 00:03:34
Took screenshot "/tmp/TailsToaster/app_spam-2015-04-11T10:03:58+00:00.png"

  Scenario: start both Gedit and Seahorse                                          # features/app_spam.feature:21

(virt-viewer:6954): Gdk-CRITICAL **: gdk_window_set_cursor: assertion 'GDK_IS_WINDOW (window)' failed
    When I start "Gedit" via the GNOME "Accessories" applications menu             # features/step_definitions/common_steps.rb:782
      execution expired (Timeout::Error)
      ./features/support/helpers/misc_helpers.rb:37:in `sleep'
      ./features/support/helpers/misc_helpers.rb:37:in `block (2 levels) in try_for'
      ./features/support/helpers/misc_helpers.rb:23:in `loop'
      ./features/support/helpers/misc_helpers.rb:23:in `block in try_for'
      ./features/support/helpers/misc_helpers.rb:22:in `try_for'
      ./features/step_definitions/common_steps.rb:775:in `gnome_app_menu_click_helper'
      ./features/step_definitions/common_steps.rb:795:in `/^I start "([^"]+)" via the GNOME "([^"]+)" applications menu$/'
      features/app_spam.feature:22:in `When I start "Gedit" via the GNOME "Accessories" applications menu'
    Then I see "GeditWindow.png" after at most 10 seconds                          # features/step_definitions/common_steps.rb:413
    When I start "Seahorse" via the GNOME "System"/"Preferences" applications menu # features/step_definitions/common_steps.rb:798
    Then I see "SeahorseWindow.png" after at most 10 seconds                       # features/step_definitions/common_steps.rb:413
Scenario failed at time 00:04:43

Will do the rest of the testing with the patch with debugging info.

#18 Updated by kytv 2015-04-12 17:54:51

• QA Check changed from Info Needed to Dev Needed

anonym wrote:

> kytv, could you please try to reproduce this and do some more testing w.r.t. if unclutter or hhpc actually have anything to do with the problem? I.e. for x in unclutter, hhpc, “neither unclutter nor hhpc”, run the test suite with x on app_spam.feature and check:
>
> * without any of my patches
>
> that heavy CPU load triggers the error often
>
> that normal CPU load never triggers the error occasionally
>
> * with I_start-fix.patch
>
> that heavy CPU load triggers the error occasionally
>
> that normal CPU load never triggers the error
>
> * with I_start-fix-with-debugging.patch
>
> that normal CPU load never triggers the error but that the number of errors it caught and fixed are about the same as without the fix (under normal load)

As I wrote above I couldn’t run with the I_start_fix.patch but the other results of mine are pretty close to yours.

With unclutter, with normal¹ load

150 scenarios (24 failed, 126 passed)
1450 steps (24 failed, 40 skipped, 1386 passed)
66m11.318s

With unclutter commented out, with normal² load

150 scenarios (2 failed, 148 passed)
1450 steps (2 failed, 2 skipped, 1446 passed)
53m20.338s

With hhpc and normal³ load

150 scenarios (6 failed, 144 passed)
1450 steps (6 failed, 10 skipped, 1434 passed)
54m20.903s

hhpc, debug patch, and normal⁴ load:

150 scenarios (150 passed)
1450 steps (1450 passed)
78m59.354s

debug patch, unclutter, and normal⁵ load

150 scenarios (150 passed)
1450 steps (1450 passed)
79m9.878s

debug patch, unclutter, insane⁶ load

150 scenarios (1 failed, 149 passed)
1450 steps (1 failed, 1449 passed)
119m16.099s

unclutter, insane load

150 scenarios (82 failed, 68 passed)
1450 steps (82 failed, 112 skipped, 1256 passed)
96m57.133s

#19 Updated by anonym 2015-04-13 07:15:23

• File deleted (I_start-fix.patch)

#20 Updated by anonym 2015-04-13 07:16:29

• File I_start-fix-fixed.patch added

kytv wrote:
> anonym wrote:
> > The previous patch was an old, bugged version.
>
> The current I_start_fix.patch fails consistently without load.

Strange, it’s like if my second upload didn’t update the file. Trying with a new filename.

#21 Updated by anonym 2015-04-13 07:31:47

• Assignee changed from anonym to kytv
• QA Check changed from Dev Needed to Info Needed

I think it’s pretty clear that something like this patch is needed since the only runs (on “normal” load) that had no failures were those with it applied. Perhaps that’s good enough to fix the problem with the I start ... steps for you. Could you please do another run with the -fixed (non-debugging) patch, with unclutter on normal and insane load?

On IRC you said that you suspected that you had seen similar click errors in some other part of the test suite. Any idea where this was?

#22 Updated by kytv 2015-04-15 12:54:25

• Assignee changed from kytv to anonym

anonym wrote:
> I think it’s pretty clear that something like this patch is needed since the only runs (on “normal” load) that had no failures were those with it applied. Perhaps that’s good enough to fix the problem with the I start ... steps for you. Could you please do another run with the -fixed (non-debugging) patch, with unclutter on normal and insane load?

After lots (and lots) of test runs, I_start-fix-fixed.patch is a clearly an improvement that the test suite needs. The suite didn’t fail with the app_spam feature under my “insane” load scenario with this applied…so I “sabotaged” it with multiple mprime instances to really peg the CPU (in the VM). At this point it started to (understandably) fail but the I_start-fix-fixed.patch kept the failures down to 2/150.

Without the patch but with this same ridiculous level of load there were more than 100 failures, consistently. At worst during this “nightmare scenario” (which almost certainly would not be an issue in reality), 140/150 failed. With the patch: 2/150 failed. Most runs with the patch were successful.

tl;dr: Applying this patch will do wonders for test suite reliability.

> On IRC you said that you suspected that you had seen similar click errors in some other part of the test suite. Any idea where this was?

No. :(

Since my discovery that the test suite, nested, was much more reliable for me without unclutter, I nearly always ran without unclutter.

I will continue running the test suite with I_start-fix-fixed.patch applied and with unclutter enabled to hopefully determine (or rule out) where else I suspected a similar problem may be.

#24 Updated by kytv 2015-04-17 12:24:33

• File 8928-TorReady.png added

I’m sure this is related (seen in my nested VM):

    Given I fetch the "10CC5BC7" OpenPGP key using the GnuPG CLI without any signatures                                 # features/step_definitions/torified_gnupg.rb:26
    And the GnuPG fetch is successful                                                                                   # features/step_definitions/torified_gnupg.rb:38
    And the "10CC5BC7" key is in the live user's public keyring after at most 120 seconds                               # features/step_definitions/torified_gnupg.rb:50
    But the key "10CC5BC7" has only 2 signatures                                                                        # features/step_definitions/torified_gnupg.rb:7
    When I start Seahorse via the Tails OpenPGP Applet                                                                  # features/step_definitions/torified_gnupg.rb:57
      FindFailed: can not find GpgAppletManageKeys.png on the screen.
      Line ?, in File ? (RuntimeError)
      features/torified_gnupg.feature:50:in `When I start Seahorse via the Tails OpenPGP Applet'
    Then Seahorse has opened                                                                                            # features/step_definitions/torified_gnupg.rb:67
    And I enable key synchronization in Seahorse                                                                        # features/step_definitions/torified_gnupg.rb:72
    And I synchronize keys in Seahorse                                                                                  # features/step_definitions/torified_gnupg.rb:84
    Then the key "10CC5BC7" has more than 2 signatures

Instead of clicking the GPGApplet icon it clicked the notification icon, causing me to see this.

Unfortunately I was not capturing a video at the time so all I have is this screenshot.

Edit:: No, it’s totally unrelated.

#26 Updated by anonym 2015-04-17 23:49:12

• Assignee changed from anonym to kytv

kytv wrote:
> Disregard Bug #8928#note-24. I saw it happen this time. In short, it went to click the applet icon but the systray wasn’t at a stable state yet, so it ended up clicking something else.

That was exactly what I was gonna suggest when I read Bug #8928#note-24. In my opinion, though, it’s still a problem and we shouldn’t disregard it. Hmm. Possibly we should do something like:

--- a/features/step_definitions/common_steps.rb
+++ b/features/step_definitions/common_steps.rb
@@ -57,6 +57,7 @@ def restore_background
       @vm.execute("service tor start")
       wait_until_tor_is_working
       @vm.spawn("restart-vidalia")
+      @screen.wait("GnomeSystrayVidalia.png", 30)
     end
   else
     @vm.host_to_guest_time_sync

OTOH, since Vidalia’s systray icon starts appears to the far left, will it actually change the order to the right, where gpgApplet’s icon is? Or is it something else? The notification systray icon?

#29 Updated by kytv 2015-04-20 18:26:15

• Assignee changed from kytv to anonym
• QA Check changed from Info Needed to Dev Needed

kytv wrote:
> Note, however, this (Bug #8928#note-24) would also be a problem in encryption.feature since it also uses the gpgApplet.
>
> […]
>
> (but this gpgApplet/systray stuff should probably go into a new ticket)

and it did, Bug #9258.

Back to this ticket, I’m continuing to run with unclutter and /code/attachments/download/735/I_start-fix-fixed.patch enabled to try to find other areas of failure.

#31 Updated by anonym 2015-04-22 03:15:43

• Assignee changed from anonym to kytv
• QA Check changed from Dev Needed to Info Needed

kytv wrote:
> kytv wrote:
> > Note, however, this (Bug #8928#note-24) would also be a problem in encryption.feature since it also uses the gpgApplet.
> >
> > […]
> >
> > (but this gpgApplet/systray stuff should probably go into a new ticket)
>
> and it did, Bug #9258.

Great!

> Back to this ticket, I’m continuing to run with unclutter and /code/attachments/download/735/I_start-fix-fixed.patch enabled to try to find other areas of failure.

Any results? Also, why did you assign the ticket to me?

#33 Updated by kytv 2015-04-22 12:38:01

• Assignee changed from kytv to anonym

anonym wrote:

> > Back to this ticket, I’m continuing to run with unclutter and /code/attachments/download/735/I_start-fix-fixed.patch enabled to try to find other areas of failure.
>
> Any results? Also, why did you assign the ticket to me?

I thought I was done, that the I_start... business was to be the solution and I’d continue testing on my own.

I’m not seeing any failures with this patch applied and with unclutter enabled. While I still think that unclutter can cause problems in some configurations, such as within nested VMs (apparently), the I_start_fix patch takes care of them and other problems caused by increased system load.

(Now re-assigning with the belief that I’ve fulfilled my obligations with this; if there’s anything else for me to do which I’ve missed please let me know).

#35 Updated by intrigeri 2015-04-25 05:44:33

• Status changed from Confirmed to In Progress

#39 Updated by anonym 2015-05-05 11:09:56

• Status changed from In Progress to Fix committed

Applied in changeset commit:89a30df38b537b178c6254ffbae00f9b47195014.

#40 Updated by anonym 2015-05-05 13:05:30

• Assignee deleted (anonym)
• QA Check changed from Info Needed to Pass
• Feature Branch set to bugfix/8928-even-more-robust-app-menus
• Type of work changed from Research to Code

Given all the positive testing, I put the patch into the bugfix/8928-even-more-robust-app-menus branch and merged it. Closing this ticket for now, but hopefully permanently.

#42 Updated by kytv 2015-05-07 14:08:29

• related to Bug #9355: More robust accessing the gpgApplet in the test suite added

#43 Updated by kytv 2015-05-07 14:09:58

• blocks Bug #9046: Update the encryption test for Jessie added

#44 Updated by BitingBird 2015-05-12 18:43:48

• Status changed from Fix committed to Resolved