1 /*
2  * Copyright (C) 2018 The Android Open Source Project
3  *
4  * Licensed under the Apache License, Version 2.0 (the "License");
5  * you may not use this file except in compliance with the License.
6  * You may obtain a copy of the License at
7  *
8  *      http://www.apache.org/licenses/LICENSE-2.0
9  *
10  * Unless required by applicable law or agreed to in writing, software
11  * distributed under the License is distributed on an "AS IS" BASIS,
12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13  * See the License for the specific language governing permissions and
14  * limitations under the License.
15  */
16 
17 #include <sstream>
18 #include <stdio.h>
19 #include <string.h>
20 #include <string>
21 #include <sys/mman.h>
22 #include <sys/types.h>
23 #include <unistd.h>
24 
25 #include <android-base/file.h>
26 #include <android-base/logging.h>
27 #include <android-base/properties.h>
28 #include <android-base/stringprintf.h>
29 #include <android-base/strings.h>
30 #include <gtest/gtest.h>
31 #include <lmkd.h>
32 #include <liblmkd_utils.h>
33 #include <log/log_properties.h>
34 #include <private/android_filesystem_config.h>
35 
36 using namespace android::base;
37 
38 #define INKERNEL_MINFREE_PATH "/sys/module/lowmemorykiller/parameters/minfree"
39 #define LMKDTEST_RESPAWN_FLAG "LMKDTEST_RESPAWN"
40 
41 #define LMKD_LOGCAT_MARKER "lowmemorykiller"
42 #define LMKD_KILL_MARKER_TEMPLATE LMKD_LOGCAT_MARKER ": Kill '%s'"
43 #define OOM_MARKER "Out of memory"
44 #define OOM_KILL_MARKER "Killed process"
45 #define MIN_LOG_SIZE 100
46 
47 #define ONE_MB (1 << 20)
48 
49 /* Test constant parameters */
50 #define OOM_ADJ_MAX 1000
51 #define OOM_ADJ_MIN 0
52 #define OOM_ADJ_STEP 100
53 #define STEP_COUNT ((OOM_ADJ_MAX - OOM_ADJ_MIN) / OOM_ADJ_STEP + 1)
54 
55 #define ALLOC_STEP (ONE_MB)
56 #define ALLOC_DELAY 1000
57 
58 /* Utility functions */
readCommand(const std::string & command)59 std::string readCommand(const std::string& command) {
60     FILE* fp = popen(command.c_str(), "r");
61     std::string content;
62     ReadFdToString(fileno(fp), &content);
63     pclose(fp);
64     return content;
65 }
66 
readLogcat(const std::string & marker)67 std::string readLogcat(const std::string& marker) {
68     std::string content = readCommand("logcat -d -b all");
69     size_t pos = content.find(marker);
70     if (pos == std::string::npos) return "";
71     content.erase(0, pos);
72     return content;
73 }
74 
writeFile(const std::string & file,const std::string & string)75 bool writeFile(const std::string& file, const std::string& string) {
76     if (getuid() == static_cast<unsigned>(AID_ROOT)) {
77         return WriteStringToFile(string, file);
78     }
79     return string == readCommand(
80         "echo -n '" + string + "' | su root tee " + file + " 2>&1");
81 }
82 
writeKmsg(const std::string & marker)83 bool writeKmsg(const std::string& marker) {
84     return writeFile("/dev/kmsg", marker);
85 }
86 
getTextAround(const std::string & text,size_t pos,size_t lines_before,size_t lines_after)87 std::string getTextAround(const std::string& text, size_t pos,
88                           size_t lines_before, size_t lines_after) {
89     size_t start_pos = pos;
90 
91     // find start position
92     // move up lines_before number of lines
93     while (lines_before > 0 &&
94            (start_pos = text.rfind('\n', start_pos)) != std::string::npos) {
95         lines_before--;
96     }
97     // move to the beginning of the line
98     start_pos = text.rfind('\n', start_pos);
99     start_pos = (start_pos == std::string::npos) ? 0 : start_pos + 1;
100 
101     // find end position
102     // move down lines_after number of lines
103     while (lines_after > 0 &&
104            (pos = text.find('\n', pos)) != std::string::npos) {
105         pos++;
106         lines_after--;
107     }
108     return text.substr(start_pos, (pos == std::string::npos) ?
109                        std::string::npos : pos - start_pos);
110 }
111 
getTaskName(std::string & name)112 bool getTaskName(std::string &name) {
113     std::string cmdline;
114 
115     if (!ReadFileToString("/proc/self/cmdline", &cmdline)) {
116         GTEST_LOG_(INFO) << "Failed to read /proc/self/cmdline";
117         return false;
118     }
119     //filter out paramters as cmdline use null bytes to separate
120     name = cmdline.c_str();
121     return true;
122 }
123 
124 /* Child synchronization primitives */
125 #define STATE_INIT 0
126 #define STATE_CHILD_READY 1
127 #define STATE_PARENT_READY 2
128 
129 struct state_sync {
130     pthread_mutex_t mutex;
131     pthread_cond_t condition;
132     int state;
133 };
134 
init_state_sync_obj()135 struct state_sync * init_state_sync_obj() {
136     struct state_sync *ssync;
137 
138     ssync = (struct state_sync*)mmap(NULL, sizeof(struct state_sync),
139                 PROT_READ | PROT_WRITE, MAP_ANONYMOUS | MAP_SHARED, -1, 0);
140     if (ssync == MAP_FAILED) {
141         return NULL;
142     }
143 
144     pthread_mutexattr_t mattr;
145     pthread_mutexattr_init(&mattr);
146     pthread_mutexattr_setpshared(&mattr, PTHREAD_PROCESS_SHARED);
147     pthread_mutex_init(&ssync->mutex, &mattr);
148 
149     pthread_condattr_t cattr;
150     pthread_condattr_init(&cattr);
151     pthread_condattr_setpshared(&cattr, PTHREAD_PROCESS_SHARED);
152     pthread_cond_init(&ssync->condition, &cattr);
153 
154     ssync->state = STATE_INIT;
155     return ssync;
156 }
157 
destroy_state_sync_obj(struct state_sync * ssync)158 void destroy_state_sync_obj(struct state_sync *ssync) {
159     pthread_cond_destroy(&ssync->condition);
160     pthread_mutex_destroy(&ssync->mutex);
161     munmap(ssync, sizeof(struct state_sync));
162 }
163 
signal_state(struct state_sync * ssync,int state)164 void signal_state(struct state_sync *ssync, int state) {
165     pthread_mutex_lock(&ssync->mutex);
166     ssync->state = state;
167     pthread_cond_signal(&ssync->condition);
168     pthread_mutex_unlock(&ssync->mutex);
169 }
170 
wait_for_state(struct state_sync * ssync,int state)171 void wait_for_state(struct state_sync *ssync, int state) {
172     pthread_mutex_lock(&ssync->mutex);
173     while (ssync->state != state) {
174         pthread_cond_wait(&ssync->condition, &ssync->mutex);
175     }
176     pthread_mutex_unlock(&ssync->mutex);
177 }
178 
179 /* Memory allocation and data sharing */
180 struct shared_data {
181     size_t allocated;
182     bool finished;
183     size_t total_size;
184     size_t step_size;
185     size_t step_delay;
186     int oomadj;
187 };
188 
189 volatile void *gptr;
add_pressure(struct shared_data * data)190 void add_pressure(struct shared_data *data) {
191     volatile void *ptr;
192     size_t allocated_size = 0;
193 
194     data->finished = false;
195     while (allocated_size < data->total_size) {
196         ptr = mmap(NULL, data->step_size, PROT_READ | PROT_WRITE,
197                 MAP_ANONYMOUS | MAP_PRIVATE, 0, 0);
198         if (ptr != MAP_FAILED) {
199             /* create ptr aliasing to prevent compiler optimizing the access */
200             gptr = ptr;
201             /* make data non-zero */
202             memset((void*)ptr, (int)(allocated_size + 1), data->step_size);
203             allocated_size += data->step_size;
204             data->allocated = allocated_size;
205         }
206         usleep(data->step_delay);
207     }
208     data->finished = (allocated_size >= data->total_size);
209 }
210 
211 /* Memory stress test main body */
runMemStressTest()212 void runMemStressTest() {
213     struct shared_data *data;
214     struct state_sync *ssync;
215     int sock;
216     pid_t pid;
217     uid_t uid = getuid();
218 
219     // check if in-kernel LMK driver is present
220     if (!access(INKERNEL_MINFREE_PATH, W_OK)) {
221         GTEST_LOG_(INFO) << "Must not have kernel lowmemorykiller driver,"
222                          << " terminating test";
223         return;
224     }
225 
226     ASSERT_FALSE((sock = lmkd_connect()) < 0)
227         << "Failed to connect to lmkd process, err=" << strerror(errno);
228 
229     /* allocate shared memory to communicate params with a child */
230     data = (struct shared_data*)mmap(NULL, sizeof(struct shared_data),
231                 PROT_READ | PROT_WRITE, MAP_ANONYMOUS | MAP_SHARED, -1, 0);
232     ASSERT_FALSE(data == MAP_FAILED) << "Memory allocation failure";
233     data->total_size = (size_t)-1; /* allocate until killed */
234     data->step_size = ALLOC_STEP;
235     data->step_delay = ALLOC_DELAY;
236 
237     /* allocate state sync object */
238     ASSERT_FALSE((ssync = init_state_sync_obj()) == NULL)
239         << "Memory allocation failure";
240 
241     /* run the test gradually decreasing oomadj */
242     data->oomadj = OOM_ADJ_MAX;
243     while (data->oomadj >= OOM_ADJ_MIN) {
244         ASSERT_FALSE((pid = fork()) < 0)
245             << "Failed to spawn a child process, err=" << strerror(errno);
246         if (pid != 0) {
247             /* Parent */
248             struct lmk_procprio params;
249             /* wait for child to start and get ready */
250             wait_for_state(ssync, STATE_CHILD_READY);
251             params.pid = pid;
252             params.uid = uid;
253             params.oomadj = data->oomadj;
254             params.ptype = PROC_TYPE_APP;
255             ASSERT_FALSE(lmkd_register_proc(sock, &params) < 0)
256                 << "Failed to communicate with lmkd, err=" << strerror(errno);
257             // signal the child it can proceed
258             signal_state(ssync, STATE_PARENT_READY);
259             waitpid(pid, NULL, 0);
260             if (data->finished) {
261                 GTEST_LOG_(INFO) << "Child [pid=" << pid << "] allocated "
262                                  << data->allocated / ONE_MB << "MB";
263             } else {
264                 GTEST_LOG_(INFO) << "Child [pid=" << pid << "] allocated "
265                                  << data->allocated / ONE_MB
266                                  << "MB before being killed";
267             }
268             data->oomadj -= OOM_ADJ_STEP;
269         } else {
270             /* Child */
271             pid = getpid();
272             GTEST_LOG_(INFO) << "Child [pid=" << pid
273                              << "] is running at oomadj="
274                              << data->oomadj;
275             data->allocated = 0;
276             data->finished = false;
277             ASSERT_FALSE(create_memcg(uid, pid) != 0)
278                 << "Child [pid=" << pid << "] failed to create a cgroup";
279             signal_state(ssync, STATE_CHILD_READY);
280             wait_for_state(ssync, STATE_PARENT_READY);
281             add_pressure(data);
282             /* should not reach here, child should be killed by OOM/LMK */
283             FAIL() << "Child [pid=" << pid << "] was not killed";
284             break;
285         }
286     }
287     destroy_state_sync_obj(ssync);
288     munmap(data, sizeof(struct shared_data));
289     close(sock);
290 }
291 
TEST(lmkd,check_for_oom)292 TEST(lmkd, check_for_oom) {
293     // test requirements
294     //   userdebug build
295     if (!__android_log_is_debuggable()) {
296         GTEST_LOG_(INFO) << "Must be userdebug build, terminating test";
297         return;
298     }
299 
300     // if respawned test process then run the test and exit (no analysis)
301     if (getenv(LMKDTEST_RESPAWN_FLAG) != NULL) {
302         runMemStressTest();
303         return;
304     }
305 
306     // Main test process
307     // mark the beginning of the test
308     std::string marker = StringPrintf(
309         "LMKD test start %lu\n", static_cast<unsigned long>(time(nullptr)));
310     ASSERT_TRUE(writeKmsg(marker));
311 
312     // get executable complete path
313     std::string task_name;
314     ASSERT_TRUE(getTaskName(task_name));
315 
316     std::string test_output;
317     if (getuid() != static_cast<unsigned>(AID_ROOT)) {
318         // if not root respawn itself as root and capture output
319         std::string command = StringPrintf(
320             "%s=true su root %s 2>&1", LMKDTEST_RESPAWN_FLAG,
321             task_name.c_str());
322         std::string test_output = readCommand(command);
323         GTEST_LOG_(INFO) << test_output;
324     } else {
325         // main test process is root, run the test
326         runMemStressTest();
327     }
328 
329     // Analyze results
330     // capture logcat containind kernel logs
331     std::string logcat_out = readLogcat(marker);
332 
333     // 1. extract LMKD kills from logcat output, count kills
334     std::stringstream kill_logs;
335     int hit_count = 0;
336     size_t pos = 0;
337     marker = StringPrintf(LMKD_KILL_MARKER_TEMPLATE, task_name.c_str());
338 
339     while (true) {
340         if ((pos = logcat_out.find(marker, pos)) != std::string::npos) {
341             kill_logs << getTextAround(logcat_out, pos, 0, 1);
342             pos += marker.length();
343             hit_count++;
344         } else {
345             break;
346         }
347     }
348     GTEST_LOG_(INFO) << "====Logged kills====" << std::endl
349                      << kill_logs.str();
350     EXPECT_TRUE(hit_count == STEP_COUNT) << "Number of kills " << hit_count
351                                          << " is less than expected "
352                                          << STEP_COUNT;
353 
354     // 2. check kernel logs for OOM kills
355     pos = logcat_out.find(OOM_MARKER);
356     bool oom_detected = (pos != std::string::npos);
357     bool oom_kill_detected = (oom_detected &&
358         logcat_out.find(OOM_KILL_MARKER, pos) != std::string::npos);
359 
360     EXPECT_FALSE(oom_kill_detected) << "OOM kill is detected!";
361     if (oom_detected || oom_kill_detected) {
362         // capture logcat with logs around all OOMs
363         pos = 0;
364         while ((pos = logcat_out.find(OOM_MARKER, pos)) != std::string::npos) {
365             GTEST_LOG_(INFO) << "====Logs around OOM====" << std::endl
366                              << getTextAround(logcat_out, pos,
367                                     MIN_LOG_SIZE / 2, MIN_LOG_SIZE / 2);
368             pos += strlen(OOM_MARKER);
369         }
370     }
371 
372     // output complete logcat with kernel (might get truncated)
373     GTEST_LOG_(INFO) << "====Complete logcat output====" << std::endl
374                      << logcat_out;
375 }
376 
377