1 /*
2  * Copyright (c) Huawei Technologies Co., Ltd. 2021. All rights reserved.
3  * Licensed under the Apache License, Version 2.0 (the "License");
4  * you may not use this file except in compliance with the License.
5  * You may obtain a copy of the License at
6  *
7  * http://www.apache.org/licenses/LICENSE-2.0
8  *
9  * Unless required by applicable law or agreed to in writing, software
10  * distributed under the License is distributed on an "AS IS" BASIS,
11  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12  * See the License for the specific language governing permissions and
13  * limitations under the License.
14  */
15 #include "hilog_plugin.h"
16 #include "securec.h"
17 
18 #include <fcntl.h>
19 #include <cinttypes>
20 #include <csignal>
21 #include <sstream>
22 #include <cstdio>
23 #include <sys/syscall.h>
24 #include <sys/types.h>
25 #include <sys/wait.h>
26 #include <unistd.h>
27 #include "common.h"
28 #include "hilog_plugin_result.pbencoder.h"
29 
30 namespace {
31 using namespace OHOS::Developtools::Profiler;
32 std::atomic<uint64_t> g_id(1);
33 const int DEC_BASE = 10;
34 const int TIME_HOUR_WIDTH = 5;
35 const int TIME_SEC_WIDTH = 14;
36 const int TIME_NS_WIDTH = 24;
37 const int FILE_NAME_LEN = 15;
38 const int TIME_BUFF_LEN = 32;
39 const int PIPE_SIZE_RATIO = 8;
40 const int BYTE_BUFFER_SIZE = 1024;
41 const int BASE_YEAR = 1900;
42 const int MAX_BUFFER_LEN = 8192;
43 const std::string DEFAULT_LOG_PATH("/data/local/tmp/");
44 FileCache g_fileCache(DEFAULT_LOG_PATH);
45 const std::string BIN_COMMAND("/system/bin/hilog");
46 } // namespace
47 
HilogPlugin()48 HilogPlugin::HilogPlugin() : fp_(nullptr, nullptr) {}
49 
~HilogPlugin()50 HilogPlugin::~HilogPlugin()
51 {
52     PROFILER_LOG_INFO(LOG_CORE, "%s: ready!", __func__);
53     std::unique_lock<std::mutex> locker(mutex_);
54     if (running_) {
55         running_ = false;
56         if (workThread_.joinable()) {
57             workThread_.join();
58         }
59     }
60     locker.unlock();
61 
62     if (protoConfig_.need_record()) {
63         g_fileCache.Close();
64     }
65     if (fp_ != nullptr) {
66         fp_.reset();
67     }
68     PROFILER_LOG_INFO(LOG_CORE, "%s: success!", __func__);
69 }
70 
Start(const uint8_t* configData, uint32_t configSize)71 int HilogPlugin::Start(const uint8_t* configData, uint32_t configSize)
72 {
73     CHECK_TRUE(protoConfig_.ParseFromArray(configData, configSize) > 0, -1, "HilogPlugin: ParseFromArray failed");
74     if (protoConfig_.need_clear()) {
75         std::vector<std::string> cmdArg;
76 
77         cmdArg.emplace_back(BIN_COMMAND); // exe file path
78         cmdArg.emplace_back("hilog"); // exe file name
79         cmdArg.emplace_back("-r");
80         volatile pid_t childPid = -1;
81         int pipeFds[2] = {-1, -1};
82         FILE* fp = COMMON::CustomPopen(cmdArg, "r", pipeFds, childPid);
83         CHECK_NOTNULL(fp, -1, "%s:clear hilog error", __func__);
84         COMMON::CustomPclose(fp, pipeFds, childPid);
85     }
86 
87     InitHilogCmd();
88     fp_ = std::unique_ptr<FILE, std::function<int (FILE*)>>(
89         COMMON::CustomPopen(fullCmd_, "r", pipeFds_, childPid_, true), [this](FILE* fp) -> int {
90             return COMMON::CustomPclose(fp, pipeFds_, childPid_, true);
91         });
92 
93     if (protoConfig_.need_record()) {
94         OpenLogFile();
95     }
96 
97     CHECK_NOTNULL(resultWriter_, -1, "HilogPlugin: Writer is no set!!");
98     CHECK_NOTNULL(resultWriter_->write, -1, "HilogPlugin: Writer.write is no set!!");
99     CHECK_NOTNULL(resultWriter_->flush, -1, "HilogPlugin: Writer.flush is no set!!");
100     g_id = 1;
101     std::unique_lock<std::mutex> locker(mutex_);
102     running_ = true;
103     locker.unlock();
104 
105     int oldPipeSize = fcntl(fileno(fp_.get()), F_GETPIPE_SZ);
106     fcntl(fileno(fp_.get()), F_SETPIPE_SZ, oldPipeSize * PIPE_SIZE_RATIO);
107     int pipeSize = fcntl(fileno(fp_.get()), F_GETPIPE_SZ);
108     PROFILER_LOG_INFO(LOG_CORE, "{fp = %d, pipeSize=%d, oldPipeSize=%d}", fileno(fp_.get()), pipeSize, oldPipeSize);
109 
110     workThread_ = std::thread([this] { this->Run(); });
111     return 0;
112 }
113 
Stop()114 int HilogPlugin::Stop()
115 {
116     PROFILER_LOG_INFO(LOG_CORE, "HilogPlugin: ready stop thread!");
117     std::unique_lock<std::mutex> locker(mutex_);
118     running_ = false;
119     COMMON::CustomPUnblock(pipeFds_);
120     locker.unlock();
121     if (workThread_.joinable()) {
122         workThread_.join();
123     }
124     if (protoConfig_.need_record() && !dataBuffer_.empty()) {
125         g_fileCache.Write(dataBuffer_.data(), dataBuffer_.size());
126         dataBuffer_.erase(dataBuffer_.begin(), dataBuffer_.end());
127     }
128     PROFILER_LOG_INFO(LOG_CORE, "HilogPlugin: stop thread success!");
129     if (protoConfig_.need_record()) {
130         g_fileCache.Close();
131     }
132     fp_.reset();
133 
134     PROFILER_LOG_INFO(LOG_CORE, "HilogPlugin: stop success!");
135     return 0;
136 }
137 
SetWriter(WriterStruct* writer)138 int HilogPlugin::SetWriter(WriterStruct* writer)
139 {
140     resultWriter_ = writer;
141     return 0;
142 }
143 
OpenLogFile()144 bool HilogPlugin::OpenLogFile()
145 {
146     char name[FILE_NAME_LEN] = {0};
147     GetDateTime(name, sizeof(name));
148     CHECK_TRUE(g_fileCache.Open(name), false, "HilogPlugin:%s failed!", __func__);
149 
150     return true;
151 }
152 
GetlevelCmd()153 std::string HilogPlugin::GetlevelCmd()
154 {
155     std::string levelCmd = "";
156     switch (protoConfig_.log_level()) {
157         case ERROR:
158             levelCmd = "E";
159             break;
160         case INFO:
161             levelCmd = "I";
162             break;
163         case DEBUG:
164             levelCmd = "D";
165             break;
166         case WARN:
167             levelCmd = "W";
168             break;
169         case FATAL:
170             levelCmd = "F";
171             break;
172         default:
173             break;
174     }
175 
176     return levelCmd;
177 }
178 
InitHilogCmd()179 void HilogPlugin::InitHilogCmd()
180 {
181     fullCmd_.emplace_back(BIN_COMMAND); // exe file path
182     fullCmd_.emplace_back("hilog"); // exe file name
183 
184     if (protoConfig_.pid() > 0) {
185         fullCmd_.emplace_back("-P");
186         fullCmd_.emplace_back(std::to_string(protoConfig_.pid()));
187     }
188     if (GetlevelCmd().length() > 0) {
189         fullCmd_.emplace_back("-L");
190         fullCmd_.emplace_back(GetlevelCmd());
191     }
192 
193     fullCmd_.emplace_back("--format");
194     fullCmd_.emplace_back("nsec");
195 }
196 
Run(void)197 void HilogPlugin::Run(void)
198 {
199     PROFILER_LOG_INFO(LOG_CORE, "HilogPlugin::Run start!");
200     std::unique_ptr<uint8_t[]> buffer = std::make_unique<uint8_t[]>(MAX_BUFFER_LEN);
201 
202     std::unique_ptr<HilogInfo> dataProto = nullptr;
203     std::unique_ptr<ProtoEncoder::HilogInfo> hilogInfo = nullptr;
204     if (resultWriter_->isProtobufSerialize) {
205         dataProto = std::make_unique<HilogInfo>();
206     } else {
207         hilogInfo = std::make_unique<ProtoEncoder::HilogInfo>(resultWriter_->startReport(resultWriter_));
208     }
209     time_t startTm = time(nullptr);
210     struct tm* pTime = localtime(&startTm);
211     char startTime[FILE_NAME_LEN] = {0};
212     if (pTime != nullptr) {
213         (void)snprintf_s(startTime, FILE_NAME_LEN, FILE_NAME_LEN - 1, "%02d-%02d %02d:%02d:%02d",
214                          pTime->tm_mon + 1, pTime->tm_mday, pTime->tm_hour, pTime->tm_min, pTime->tm_sec);
215     }
216 
217     while (running_) {
218         if (fgets(reinterpret_cast<char*>(buffer.get()), MAX_BUFFER_LEN - 1, fp_.get()) == nullptr) {
219             continue;
220         }
221 
222         if ((strlen(reinterpret_cast<char*>(buffer.get())) + 1) == (MAX_BUFFER_LEN - 1)) {
223             PROFILER_LOG_ERROR(LOG_CORE,
224                                "HilogPlugin:data length is greater than the MAX_BUFFER_LEN(%d)", MAX_BUFFER_LEN);
225         }
226 
227         auto cptr = reinterpret_cast<char*>(buffer.get());
228         std::string curTime = cptr;
229         curTime = curTime.substr(0, TIME_SEC_WIDTH);
230         if (curTime < startTime) {
231             continue;
232         }
233         if (resultWriter_->isProtobufSerialize) {
234             ParseLogLineData(cptr, strlen(cptr), dataProto.get());
235 
236             if (dataProto->ByteSizeLong() >= BYTE_BUFFER_SIZE) {
237                 FlushData(dataProto.get());
238                 dataProto.reset();
239                 dataProto = std::make_unique<HilogInfo>();
240             }
241         } else {
242             ParseLogLineData(cptr, strlen(cptr), hilogInfo.get());
243 
244             if (hilogInfo->Size() >= BYTE_BUFFER_SIZE) {
245                 FlushDataOptimize(hilogInfo.get());
246                 hilogInfo.reset();
247                 hilogInfo = std::make_unique<ProtoEncoder::HilogInfo>(resultWriter_->startReport(resultWriter_));
248             }
249         }
250 
251         if (protoConfig_.need_record() && dataBuffer_.size() >= BYTE_BUFFER_SIZE) {
252             g_fileCache.Write(dataBuffer_.data(), dataBuffer_.size());
253             dataBuffer_.erase(dataBuffer_.begin(), dataBuffer_.end());
254         }
255     }
256 
257     if (resultWriter_->isProtobufSerialize) {
258         FlushData(dataProto.get());
259         dataProto.reset();
260     } else {
261         FlushDataOptimize(hilogInfo.get());
262         hilogInfo.reset();
263     }
264     PROFILER_LOG_INFO(LOG_CORE, "HilogPlugin::Run done!");
265 }
266 
ParseLogLineInfo(const char* data, size_t len, T& hilogLineInfo)267 template <typename T> void HilogPlugin::ParseLogLineInfo(const char* data, size_t len, T& hilogLineInfo)
268 {
269     if (data == nullptr || len < TIME_NS_WIDTH) {
270         PROFILER_LOG_ERROR(LOG_CORE, "HilogPlugin:%s param invalid", __func__);
271         return;
272     }
273 
274     for (size_t i = 0; i < len && protoConfig_.need_record(); i++) {
275         dataBuffer_.push_back(data[i]);
276     }
277 
278     SetHilogLineDetails(data, hilogLineInfo);
279     return;
280 }
281 
ParseLogLineData(const char* data, size_t len, T hilogInfoProto)282 template <typename T> void HilogPlugin::ParseLogLineData(const char* data, size_t len, T hilogInfoProto)
283 {
284     CHECK_NOTNULL(data, NO_RETVAL, "data is nullptr");
285     if (*data >= '0' && *data <= '9') {
286         auto* info = hilogInfoProto->add_info();
287         ParseLogLineInfo(data, len, *info);
288         info->set_id(g_id);
289         g_id++;
290     }
291 }
292 
SetHilogLineDetails(const char* data, T& hilogLineInfo)293 template <typename T> bool HilogPlugin::SetHilogLineDetails(const char* data, T& hilogLineInfo)
294 {
295     char* end = nullptr;
296     struct timespec ts = {0};
297     char* pTmp = const_cast<char*>(data);
298 
299     TimeStringToNS(data, &ts);
300     auto* detail = hilogLineInfo.mutable_detail();
301     detail->set_tv_sec(ts.tv_sec);
302     detail->set_tv_nsec(ts.tv_nsec);
303     pTmp = pTmp + TIME_SEC_WIDTH;
304     CHECK_TRUE(FindFirstSpace(&pTmp), false, "HilogPlugin:FindFirstSpace failed!");
305     uint32_t value = static_cast<uint32_t>(strtoul(pTmp, &end, DEC_BASE));
306     CHECK_TRUE(value > 0, false, "HilogPlugin:strtoull pid failed!");
307     detail->set_pid(value);
308     pTmp = end;
309     value = static_cast<uint32_t>(strtoul(pTmp, &end, DEC_BASE));
310     CHECK_TRUE(value > 0, false, "HilogPlugin:strtoull tid failed!");
311     detail->set_tid(value);
312     pTmp = end;
313     CHECK_TRUE(RemoveSpaces(&pTmp), false, "HilogPlugin:RemoveSpaces failed!");
314     detail->set_level(*pTmp);
315     pTmp++;
316     CHECK_TRUE(RemoveSpaces(&pTmp), false, "HilogPlugin:RemoveSpaces failed!");
317 
318     if (*pTmp >= '0' && *pTmp <= '9') {
319         while (*pTmp != '/') { // 找 '/'
320             if (*pTmp == '\0' || *pTmp == '\n') {
321                 return false;
322             }
323             pTmp++;
324         }
325         pTmp++;
326         end = pTmp;
327     } else if ((*pTmp >= 'a' && *pTmp <= 'z') || (*pTmp >= 'A' && *pTmp <= 'Z')) {
328         end = pTmp;
329     }
330     int index = 1;
331     if (end == nullptr) {
332         return false;
333     }
334     while (*pTmp != ':') { // 结束符 ':'
335         if (*pTmp == '\0' || *pTmp == '\n') {
336             return false;
337         }
338         pTmp++;
339         index++;
340     }
341     detail->set_tag(std::string(end, end + index - 1));
342     pTmp++;
343     CHECK_TRUE(RemoveSpaces(&pTmp), false, "HilogPlugin: RemoveSpaces failed!");
344     size_t dataLen = strlen(pTmp) > 1 ? strlen(pTmp) -1 : 0;
345     if (google::protobuf::internal::IsStructurallyValidUTF8(pTmp, dataLen)) {
346         hilogLineInfo.set_context(pTmp, dataLen);  // - \n
347     } else {
348         PROFILER_LOG_ERROR(LOG_CORE, "HilogPlugin: log context include invalid UTF-8 data");
349         hilogLineInfo.set_context("");
350     }
351 
352     return true;
353 }
354 
FindFirstNum(char** p)355 bool HilogPlugin::FindFirstNum(char** p)
356 {
357     CHECK_NOTNULL(*p, false, "HilogPlugin:%s", __func__);
358     while (**p > '9' || **p < '0') {
359         if (**p == '\0' || **p == '\n') {
360             return false;
361         }
362         (*p)++;
363     }
364     return true;
365 }
366 
RemoveSpaces(char** p)367 bool HilogPlugin::RemoveSpaces(char** p)
368 {
369     CHECK_NOTNULL(*p, false, "HilogPlugin:%s", __func__);
370     if (**p == '\0' || **p == '\n') {
371         return false;
372     }
373     while (**p == ' ') {
374         (*p)++;
375         if (**p == '\0' || **p == '\n') {
376             return false;
377         }
378     }
379     return true;
380 }
381 
FindFirstSpace(char** p)382 bool HilogPlugin::FindFirstSpace(char** p)
383 {
384     CHECK_NOTNULL(*p, false, "HilogPlugin:%s", __func__);
385     while (**p != ' ') {
386         if (**p == '\0' || **p == '\n') {
387             return false;
388         }
389         (*p)++;
390     }
391     return true;
392 }
393 
StringToL(const char* word, long& value)394 bool HilogPlugin::StringToL(const char* word, long& value)
395 {
396     char* end = nullptr;
397     errno = 0;
398     value = strtol(word, &end, DEC_BASE);
399     if ((errno == ERANGE && (value == LONG_MAX)) || (errno != 0 && value == 0)) {
400         return false;
401     } else if (end == word && (*word >= '0' && *word <= '9')) {
402         return false;
403     }
404 
405     return true;
406 }
407 
TimeStringToNS(const char* data, struct timespec *tsTime)408 bool HilogPlugin::TimeStringToNS(const char* data, struct timespec *tsTime)
409 {
410     struct tm tmTime = {0};
411     struct tm result;
412     time_t timetTime;
413     char* end = nullptr;
414     char* pTmp = nullptr;
415     time_t nSeconds = time(nullptr);
416     uint32_t nsec = 0;
417     long fixHour = 0;
418 
419     if (localtime_r(&nSeconds, &result) == nullptr) {
420         const int bufSize = 128;
421         char buf[bufSize] = { 0 };
422         strerror_r(errno, buf, bufSize);
423         PROFILER_LOG_ERROR(LOG_CORE, "HilogPlugin: get localtime failed!, errno(%d:%s)", errno, buf);
424         return false;
425     }
426     tmTime.tm_year = result.tm_year;
427     strptime(data, "%m-%d %H:%M:%S", &tmTime);
428     pTmp = const_cast<char*>(data) + TIME_HOUR_WIDTH;
429     CHECK_TRUE(StringToL(pTmp, fixHour), false, "%s:strtol fixHour failed", __func__);
430     if (static_cast<int>(fixHour) != tmTime.tm_hour) { // hours since midnight - [0, 23]
431         PROFILER_LOG_INFO(LOG_CORE, "HilogPlugin: hour(%d) <==> fix hour(%ld)!", tmTime.tm_hour, fixHour);
432         tmTime.tm_hour = fixHour;
433     }
434     pTmp = const_cast<char*>(data) + TIME_SEC_WIDTH;
435     FindFirstNum(&pTmp);
436     nsec = static_cast<uint32_t>(strtoul(pTmp, &end, DEC_BASE));
437     CHECK_TRUE(nsec > 0, false, "%s:strtoull nsec failed", __func__);
438 
439     timetTime = mktime(&tmTime);
440     tsTime->tv_sec = timetTime;
441     tsTime->tv_nsec = nsec;
442 
443     char buff[TIME_BUFF_LEN] = {0};
444     if (snprintf_s(buff, sizeof(buff), sizeof(buff) - 1, "%ld.%09u\n", timetTime, nsec) < 0) {
445         PROFILER_LOG_ERROR(LOG_CORE, "%s:snprintf_s error", __func__);
446     }
447     size_t buffSize = strlen(buff);
448     for (size_t i = 0; i < buffSize && protoConfig_.need_record(); i++) {
449         dataBuffer_.push_back(buff[i]);
450     }
451 
452     return true;
453 }
454 
GetDateTime(char* psDateTime, uint32_t size)455 int HilogPlugin::GetDateTime(char* psDateTime, uint32_t size)
456 {
457     CHECK_NOTNULL(psDateTime, -1, "HilogPlugin:%s param invalid", __func__);
458     CHECK_TRUE(size > 1, -1, "HilogPlugin:%s param invalid!", __func__);
459 
460     time_t nSeconds;
461     struct tm* pTM;
462 
463     nSeconds = time(nullptr);
464     pTM = localtime(&nSeconds);
465     if (pTM == nullptr) {
466         const int bufSize = 128;
467         char buf[bufSize] = { 0 };
468         strerror_r(errno, buf, bufSize);
469         PROFILER_LOG_ERROR(LOG_CORE, "HilogPlugin: get localtime failed!, errno(%d:%s)", errno, buf);
470         return -1;
471     }
472 
473     if (snprintf_s(psDateTime, size, size - 1, "%04d%02d%02d%02d%02d%02d", pTM->tm_year + BASE_YEAR, pTM->tm_mon + 1,
474                    pTM->tm_mday, pTM->tm_hour, pTM->tm_min, pTM->tm_sec) < 0) {
475         PROFILER_LOG_ERROR(LOG_CORE, "%s:snprintf_s error", __func__);
476     }
477 
478     return 0;
479 }
480 
FlushData(const T hilogLineProto)481 template <typename T> void HilogPlugin::FlushData(const T hilogLineProto)
482 {
483     protoBuffer_.resize(hilogLineProto->ByteSizeLong());
484     hilogLineProto->SerializeToArray(protoBuffer_.data(), protoBuffer_.size());
485     resultWriter_->write(resultWriter_, protoBuffer_.data(), protoBuffer_.size());
486     resultWriter_->flush(resultWriter_);
487 }
488 
FlushDataOptimize(const T hilogLineProto)489 template <typename T> void HilogPlugin::FlushDataOptimize(const T hilogLineProto)
490 {
491     int messageLen = hilogLineProto->Finish();
492     resultWriter_->finishReport(resultWriter_, messageLen);
493     resultWriter_->flush(resultWriter_);
494 }