Bug #9924

"AppArmor has denied" test is fragile

Added by intrigeri 2015-08-06 05:47:42 . Updated 2015-08-11 10:41:23 .

Status:
Resolved
Priority:
High
Assignee:
Category:
Test suite
Target version:
Tails_1.5
Start date:
2015-08-06
Due date:
% Done:

100%

Feature Branch:
bugfix/9924-apparmor-has-denied-step-is-fragile
Type of work:
Code
Blueprint:

Starter:
Affected tool:
Instant Messaging
Deliverable for:

Description

features/pidgin.feature:91 fails for me: it says that AppArmor has not denied access; I’ve done the same test manually and it worked at least once.

I think that it’s because of audit_printk_skb: 69 callbacks suppressed, because if I retry by hand after taking control of TailsToaster, I can sometimes make the line appear in syslog, and sometimes not.

Not sure how to fix that, perhaps by silencing some of the deny logging that we don’t care about, to ensure that whatever is useful is actually logged? Or temporarily reconfiguring whatever suppresses these callbacks (rsyslog? the kernel audit subsystem?) in the test suite so that it stops doing that?

Subtasks

History

#1 Updated by intrigeri 2015-08-06 06:00:49

We could simply revert the Pidgin part of commit:0ea3694, but I suspect that the very same problem will appear in other scenarios that rely on the “AppArmor has denied” step, sooner or later, so a real solution would be better.

#2 Updated by intrigeri 2015-08-06 09:21:00

  • Assignee set to anonym

anonym, do you want to give it a try? (it’s a regression brought by Feature #8548 if I understand clearly)

#3 Updated by intrigeri 2015-08-06 09:21:17

  • Subject changed from AppArmor has denied "/usr/bin/pidgin" from opening "/home/amnesia/.gnupg/test.crt" test is fragile to "AppArmor has denied" test is fragile

#4 Updated by anonym 2015-08-07 13:31:12

intrigeri wrote:
> I think that it’s because of audit_printk_skb: 69 callbacks suppressed, because if I retry by hand after taking control of TailsToaster, I can sometimes make the line appear in syslog, and sometimes not.

This is also suggested on the AppArmor wiki: “the kernel may perform rate limiting which could cause AppArmor denials to be discarded”. The suggested fix is:

sysctl -w kernel.printk_ratelimit=0@

The question is how to apply this in a nice way. A dedicated “linux printk rate limiting is disabled” step that one has to remember to use before trying to trigger any AppArmor denial? It seems a bit obscure without a comment.

> We could simply revert the Pidgin part of commit:0ea3694, but I suspect that the very same problem will appear in other scenarios that rely on the “AppArmor has denied” step, sooner or later, so a real solution would be better.

A real fix, like the above one potentially is, would be preferred. I’ll try it, first by trying to get a way to reliably get the denials to be discarded. I actually never saw this, but I admittedly didn’t run the test many times against anything but the browser, since that was what I was focusing on.

> (it’s a regression brought by Feature #8548 if I understand clearly)

Yes. I had to add something like this since we don’t get any user feedback in the browser any more (Bug #9895) and then I thought it would be neat to improve these other scenarios where we try to verify our AppArmor profiles.

#5 Updated by intrigeri 2015-08-07 14:03:26

> The suggested fix is:

Excellent!

> The question is how to apply this in a nice way. A dedicated “linux printk rate limiting is disabled” step that one has to remember to use before trying to trigger any AppArmor denial? It seems a bit obscure without a comment.

We could do that in the “AppArmor has not denied” step, that in theory we should always run before “AppArmor has denied” one.
It’s a bit obscure too, but perhaps good enough. What do you think?

#6 Updated by anonym 2015-08-07 15:01:17

intrigeri wrote:
> > The question is how to apply this in a nice way. A dedicated “linux printk rate limiting is disabled” step that one has to remember to use before trying to trigger any AppArmor denial? It seems a bit obscure without a comment.
>
> We could do that in the “AppArmor has not denied” step, that in theory we should always run before “AppArmor has denied” one.
> It’s a bit obscure too, but perhaps good enough. What do you think?

It’s obscure and while it would work for how we currently use that step, I could imagine future uses of this step where this would be forgotten and causing issues. Consider something like this:

    When I run "some_application"
    Then AppArmor has not denied "some_application" from opening "some_file"

Let’s say that “some_application” actually is denied opening “some_file”, but due to printk rate limiting that particular entry was dropped. Then this step will succeed while it should not.

Hmm, I think I have a much better solution. Imagine something like this:

    Given I monitor the AppArmor log of "some_application"
    When I run "some_application"
    Then AppArmor has not denied "some_application" from opening "some_file"

The “I monitor” step will disable printk rate limiting and also store the uptime in seconds into @apparmor_profile_monitoring_start["some_profile"]. Any use of the ‘AppArmor has not denied “some_application”’ step would then look at only entries after @apparmor_profile_monitoring_start["some_profile"] in syslog. This looks much cleaner than the current situation to me as we can drop the “anti-test” checking before the “I run” step, like we currently do. Probably we should also make it a precondition that the “I monitor” step is run before.

#7 Updated by intrigeri 2015-08-08 01:20:33

> Hmm, I think I have a much better solution.

I like it. And then maybe we can also stop emptying syslog.

#8 Updated by anonym 2015-08-08 06:33:35

  • Assignee deleted (anonym)
  • % Done changed from 0 to 50
  • QA Check set to Ready for QA
  • Feature Branch set to bugfix/9924-apparmor-has-denied-step-is-fragile

anonym wrote:
> intrigeri wrote:
> > I think that it’s because of audit_printk_skb: 69 callbacks suppressed, because if I retry by hand after taking control of TailsToaster, I can sometimes make the line appear in syslog, and sometimes not.
>
> This is also suggested on the AppArmor wiki: “the kernel may perform rate limiting which could cause AppArmor denials to be discarded”. The suggested fix is:

So I verified that the suggested fix solves our problem. I ran this:

dmesg -C >/dev/null; for i in $(seq 20); do tcpdump -w /root/bin/asdf; done; clear; dmesg | less


and counted the number of denials. Note that the tcpdump profile denies access to /root/bin/. Results:

  • With the default kernel.printk_ratelimit I only get 10 denials (which is expected from my reading of https://lwn.net/Articles/66091/)
  • With rate limiting disabled (i.e. the suggested fix) I get all 20 expected denials.

#9 Updated by anonym 2015-08-08 06:34:30

  • Status changed from Confirmed to In Progress

Applied in changeset commit:3dc31b37e7ada211a5d6101f1415d8edf2f64c8d.

#10 Updated by anonym 2015-08-08 06:43:47

  • Assignee set to kytv

#11 Updated by anonym 2015-08-08 06:49:33

Here’s a minimal list of only the affected scenarios (and some that are needed due to @keep_volumes) to try the branch:

features/evince.feature:23 features/evince.feature:46 features/evince.feature:57 features/evince.feature:65 features/pidgin.feature:91 features/torified_browsing.feature:65 features/totem.feature:15 features/totem.feature:59 features/totem.feature:69

#12 Updated by kytv 2015-08-08 09:45:58

  • Assignee changed from kytv to intrigeri

Code looks good, tests pass.

When I tried the minimal featuresets I received failures like the following:

 @keep_volumes
  Scenario: I can view and print a PDF file stored in persistent /home/amnesia/Persistent                          # features/evince.feature:57
    Given a computer                                                                                               # features/step_definitions/common_steps.rb:77
    And I start Tails from USB drive "current" with network unplugged and I login with persistence password "asdf" # features/step_definitions/common_steps.rb:187
      Call to virStorageVolLookupByName failed: Storage volume not found: no storage vol with matching name 'current' (Libvirt::RetrieveError)
      ./features/support/helpers/storage_helper.rb:124:in `lookup_volume_by_name'
      ./features/support/helpers/storage_helper.rb:124:in `disk_path'
      ./features/support/helpers/vm_helper.rb:210:in `plug_drive'
      ./features/support/helpers/vm_helper.rb:261:in `set_disk_boot'
      ./features/step_definitions/common_steps.rb:94:in `/^the computer is set to boot from (.+?) drive "(.+?)"$/'
      ./features/step_definitions/common_steps.rb:190:in `/^I start Tails from (.+?) drive "(.+?)"(| with network unplugged) and I login(| with(| read-only) persistence password "([^"]+)")$/'
      features/evince.feature:59:in `And I start Tails from USB drive "current" with network unplugged and I login with persistence password "asdf"'

so I ran the full features.

#13 Updated by intrigeri 2015-08-08 10:18:57

  • Status changed from In Progress to Fix committed
  • % Done changed from 50 to 100

Applied in changeset commit:01487f76aaf0d9789e24aa1753499991b0e04cf0.

#14 Updated by intrigeri 2015-08-08 10:25:55

  • Assignee deleted (intrigeri)
  • QA Check changed from Ready for QA to Pass

For the record:

intrigeri: anonym: what's the rationale for having "start" vs. "restart" in the new step for <del><a class='issue tracker-1 status-3 priority-6 priority-default closed child' href='/code/issues/9924' title='&#34;AppArmor has denied&#34; test is fragile'>Bug #9924</a></del>?
intrigeri: anonym: from a test writer and reviewer PoV, it feels like that's something I should be careful about, while... it's a noop.
intrigeri: anonym: IOW, it seems like it pretends to expose a non-existing implementation detail.
intrigeri: anonym: now, I understand it would feel weird sometimes to write "I start" twice in the same scenario.
intrigeri: anyway, that's not a blocker.

#15 Updated by BitingBird 2015-08-11 10:41:23

  • Status changed from Fix committed to Resolved