Merge pull request #4 from runloopai/install-otel

Add OTEL

Author: dines-rl

src/bk_download.cpp

@@ -62,8 +62,17 @@ void BkDownload::switch_to_local_file() {
 }
 
 bool BkDownload::download_done() {
+    auto tracer = overlaybd_otel::get_tracer("overlaybd");
+    auto parent_span = opentelemetry::trace::Tracer::GetCurrentSpan();
+    opentelemetry::trace::StartSpanOptions options;
+    options.parent = parent_span->GetContext();
+    auto span = tracer->StartSpan("overlaybd.download.verify_and_commit", {}, {}, options);
+    auto scope = tracer->WithActiveSpan(span);
+
     auto lfs = new_localfs_adaptor();
     if (!lfs) {
+        span->SetAttribute("error", "failed_to_create_fs_adaptor");
+        span->End();
         LOG_ERROR("new_localfs_adaptor() return NULL");
         return false;
     }
@@ -72,10 +81,18 @@ bool BkDownload::download_done() {
     std::string old_name, new_name;
     old_name = dir + "/" + DOWNLOAD_TMP_NAME;
     new_name = dir + "/" + COMMIT_FILE_NAME;
+    span->SetAttribute("temp_file", old_name);
+    span->SetAttribute("commit_file", new_name);
 
     // verify sha256
     photon::semaphore done;
     std::string shares;
+    opentelemetry::trace::StartSpanOptions verify_options;
+    verify_options.parent = opentelemetry::trace::Tracer::GetCurrentSpan()->GetContext();
+    auto verify_span = tracer->StartSpan("sha256_verification", {}, {}, verify_options);
+    auto verify_scope = tracer->WithActiveSpan(verify_span);
+    verify_span->SetAttribute("expected_digest", digest);
+
     std::thread sha256_thread([&]() {
         shares = sha256sum(old_name.c_str());
         done.signal(1);
@@ -84,33 +101,90 @@ bool BkDownload::download_done() {
     // wait verify finish
     done.wait(1);
 
+    verify_span->SetAttribute("actual_digest", shares);
+    verify_span->SetAttribute("success", shares == digest);
+    verify_span->End();
+
     if (shares != digest) {
+        span->SetAttribute("error", "checksum_mismatch");
+        span->SetAttribute("expected_digest", digest);
+        span->SetAttribute("actual_digest", shares);
+        span->End();
         LOG_ERROR("verify checksum ` failed (expect: `, got: `)", old_name, digest, shares);
         force_download = true; // force redownload next time
         return false;
     }
 
+    opentelemetry::trace::StartSpanOptions rename_options;
+    rename_options.parent = opentelemetry::trace::Tracer::GetCurrentSpan()->GetContext();
+    auto rename_span = tracer->StartSpan("rename_to_commit", {}, {}, rename_options);
+    auto rename_scope = tracer->WithActiveSpan(rename_span);
     int ret = lfs->rename(old_name.c_str(), new_name.c_str());
+    rename_span->SetAttribute("success", ret == 0);
+
     if (ret != 0) {
+        span->SetAttribute("error", "rename_failed");
+        span->End();
         LOG_ERRNO_RETURN(0, false, "rename(`,`) failed", old_name, new_name);
     }
+
+    span->SetAttribute("success", true);
     LOG_INFO("download verify done. rename(`,`) success", old_name, new_name);
+    span->End();
     return true;
 }
 
 bool BkDownload::download() {
+    auto tracer = overlaybd_otel::get_tracer("overlaybd");
+    // Get current span context from parent if it exists
+    auto parent_span = opentelemetry::trace::Tracer::GetCurrentSpan();
+    opentelemetry::trace::StartSpanOptions options;
+    options.parent = parent_span->GetContext();
+    auto span = tracer->StartSpan("overlaybd.download.lifecycle", {}, {}, options);
+    auto scope = tracer->WithActiveSpan(span);
+
+    span->SetAttribute("url", url);
+    span->SetAttribute("dir", dir);
+    span->SetAttribute("file_size", file_size);
+
     if (check_downloaded(dir)) {
+        opentelemetry::trace::StartSpanOptions local_options;
+        local_options.parent = opentelemetry::trace::Tracer::GetCurrentSpan()->GetContext();
+        auto local_span = tracer->StartSpan("overlaybd.download.switch_to_local", {}, {}, local_options);
+        auto local_scope = tracer->WithActiveSpan(local_span);
         switch_to_local_file();
+        span->SetAttribute("from_cache", true);
+        span->End();
         return true;
     }
 
+    span->SetAttribute("from_cache", false);
+    bool success = false;
     if (download_blob()) {
-        if (!download_done())
+        opentelemetry::trace::StartSpanOptions verify_options;
+        verify_options.parent = opentelemetry::trace::Tracer::GetCurrentSpan()->GetContext();
+        auto verify_span = tracer->StartSpan("overlaybd.download.verify", {}, {}, verify_options);
+        auto verify_scope = tracer->WithActiveSpan(verify_span);
+        if (!download_done()) {
+            verify_span->SetAttribute("success", false);
+            span->SetAttribute("success", false);
+            span->End();
             return false;
+        }
+        verify_span->SetAttribute("success", true);
+        verify_span->End();
+
+        opentelemetry::trace::StartSpanOptions switch_options;
+        switch_options.parent = opentelemetry::trace::Tracer::GetCurrentSpan()->GetContext();
+        auto switch_span = tracer->StartSpan("overlaybd.download.switch_to_local", {}, {}, switch_options);
+        auto switch_scope = tracer->WithActiveSpan(switch_span);
         switch_to_local_file();
-        return true;
+        success = true;
     }
-    return false;
+
+    span->SetAttribute("success", success);
+    span->End();
+    return success;
 }
 
 bool BkDownload::lock_file() {
@@ -127,15 +201,26 @@ void BkDownload::unlock_file() {
 }
 
 bool BkDownload::download_blob() {
+    auto tracer = overlaybd_otel::get_tracer("overlaybd");
+    auto parent_span = opentelemetry::trace::Tracer::GetCurrentSpan();
+    opentelemetry::trace::StartSpanOptions options;
+    options.parent = parent_span->GetContext();
+    auto span = tracer->StartSpan("overlaybd.download.blob", {}, {}, options);
+    auto scope = tracer->WithActiveSpan(span);
+
     std::string dl_file_path = dir + "/" + DOWNLOAD_TMP_NAME;
+    span->SetAttribute("download_path", dl_file_path);
+    span->SetAttribute("try_count", try_cnt);
     try_cnt--;
+
     IFile *src = src_file;
     if (limit_MB_ps > 0) {
         ThrottleLimits limits;
         limits.R.throughput = limit_MB_ps * 1024UL * 1024; // MB
         limits.R.block_size = 1024UL * 1024;
         limits.time_window = 1UL;
         src = new_throttled_file(src, limits);
+        span->SetAttribute("throttle_limit_mbps", limit_MB_ps);
     }
     DEFER({
         if (limit_MB_ps > 0)
@@ -144,6 +229,8 @@ bool BkDownload::download_blob() {
 
     auto dst = open_localfile_adaptor(dl_file_path.c_str(), O_RDWR | O_CREAT, 0644);
     if (dst == nullptr) {
+        span->SetAttribute("error", "failed_to_open_dst");
+        span->End();
         LOG_ERRNO_RETURN(0, false, "failed to open dst file `", dl_file_path.c_str());
     }
     DEFER(delete dst;);
@@ -154,13 +241,22 @@ bool BkDownload::download_blob() {
     void *buff = nullptr;
     // buffer allocate, with 4K alignment
     ::posix_memalign(&buff, ALIGNMENT, bs);
-    if (buff == nullptr)
+    if (buff == nullptr) {
+        span->SetAttribute("error", "failed_to_allocate_buffer");
+        span->End();
         LOG_ERRNO_RETURN(0, false, "failed to allocate buffer with ", VALUE(bs));
+    }
     DEFER(free(buff));
 
     LOG_INFO("download blob start. (`)", url);
+    uint64_t total_bytes_read = 0;
+    uint64_t total_bytes_written = 0;
+    uint64_t retries = 0;
+
     while (offset < (ssize_t)file_size) {
         if (running != 1) {
+            span->SetAttribute("error", "download_interrupted");
+            span->End();
             LOG_INFO("image file exit when background downloading");
             return false;
         }
@@ -170,6 +266,7 @@ bool BkDownload::download_blob() {
             if (hole_pos >= offset + (ssize_t)bs) {
                 // alread downloaded
                 offset += bs;
+                total_bytes_written += bs;
                 continue;
             }
         }
@@ -179,44 +276,88 @@ bool BkDownload::download_blob() {
         if (offset + count > file_size)
             count = file_size - offset;
     again_read:
-        if (!(retry--))
+        if (!(retry--)) {
+            span->SetAttribute("error", "max_read_retries_exceeded");
+            span->SetAttribute("failed_offset", offset);
+            span->End();
             LOG_ERROR_RETURN(EIO, false, "failed to read at ", VALUE(offset), VALUE(count));
+        }
         ssize_t rlen;
         {
+            auto read_span = tracer->StartSpan("overlaybd.download.read_block");
+            auto read_scope = tracer->WithActiveSpan(read_span);
+            read_span->SetAttribute("offset", offset);
+            read_span->SetAttribute("size", count);
             SCOPE_AUDIT("bk_download", AU_FILEOP(url, offset, rlen));
             rlen = src->pread(buff, bs, offset);
+            if (rlen >= 0) {
+                read_span->SetAttribute("bytes_read", rlen);
+                total_bytes_read += rlen;
+            }
+            read_span->End();
         }
         if (rlen < 0) {
+            retries++;
             LOG_WARN("failed to read at ", VALUE(offset), VALUE(count), VALUE(errno), " retry...");
             goto again_read;
         }
         retry = 2;
     again_write:
-        if (!(retry--))
+        if (!(retry--)) {
+            span->SetAttribute("error", "max_write_retries_exceeded");
+            span->SetAttribute("failed_offset", offset);
+            span->End();
             LOG_ERROR_RETURN(EIO, false, "failed to write at ", VALUE(offset), VALUE(count));
+        }
+        auto write_span = tracer->StartSpan("overlaybd.download.write_block");
+        auto write_scope = tracer->WithActiveSpan(write_span);
+        write_span->SetAttribute("offset", offset);
+        write_span->SetAttribute("size", count);
         auto wlen = dst->pwrite(buff, count, offset);
+        if (wlen >= 0) {
+            write_span->SetAttribute("bytes_written", wlen);
+            total_bytes_written += wlen;
+        }
+        write_span->End();
         // but once write lenth larger than read length treats as OK
         if (wlen < rlen) {
+            retries++;
             LOG_WARN("failed to write at ", VALUE(offset), VALUE(count), VALUE(errno), " retry...");
             goto again_write;
         }
         offset += count;
     }
+
+    span->SetAttribute("total_bytes_read", total_bytes_read);
+    span->SetAttribute("total_bytes_written", total_bytes_written);
+    span->SetAttribute("total_retries", retries);
+    span->SetAttribute("success", true);
     LOG_INFO("download blob done. (`)", dl_file_path);
+    span->End();
     return true;
 }
 
 void bk_download_proc(std::list<BKDL::BkDownload *> &dl_list, uint64_t delay_sec, int &running) {
+    auto tracer = overlaybd_otel::get_tracer("overlaybd");
+    auto span = tracer->StartSpan("background_download_process");
+    auto scope = tracer->WithActiveSpan(span);
+    
+    span->SetAttribute("delay_seconds", delay_sec);
+    span->SetAttribute("initial_queue_size", dl_list.size());
+    
     LOG_INFO("BACKGROUND DOWNLOAD THREAD STARTED.");
     uint64_t time_st = photon::now;
     while (photon::now - time_st < delay_sec * 1000000) {
         photon::thread_usleep(200 * 1000);
-        if (running != 1)
+        if (running != 1) {
+            span->SetAttribute("early_exit", "delay_interrupted");
             break;
+        }
     }
 
     while (!dl_list.empty()) {
         if (running != 1) {
+            span->SetAttribute("early_exit", "image_exited");
             LOG_WARN("image exited, background download exit...");
             break;
         }
@@ -225,9 +366,16 @@ void bk_download_proc(std::list<BKDL::BkDownload *> &dl_list, uint64_t delay_sec
         BKDL::BkDownload *dl_item = dl_list.front();
         dl_list.pop_front();
 
+        auto dl_span = tracer->StartSpan("download_item");
+        auto dl_scope = tracer->WithActiveSpan(dl_span);
+        dl_span->SetAttribute("directory", dl_item->dir);
+        dl_span->SetAttribute("retry_count", dl_item->try_cnt);
+
         LOG_INFO("start downloading for dir `", dl_item->dir);
 
         if (!dl_item->lock_file()) {
+            dl_span->SetAttribute("status", "lock_failed");
+            dl_span->End();
             dl_list.push_back(dl_item);
             continue;
         }
@@ -236,22 +384,31 @@ void bk_download_proc(std::list<BKDL::BkDownload *> &dl_list, uint64_t delay_sec
         dl_item->unlock_file();
 
         if (running != 1) {
+            dl_span->SetAttribute("status", "interrupted");
+            dl_span->End();
             LOG_WARN("image exited, background download exit...");
             delete dl_item;
             break;
         }
 
         if (!succ && dl_item->try_cnt > 0) {
+            dl_span->SetAttribute("status", "retry");
+            dl_span->End();
             dl_list.push_back(dl_item);
             LOG_WARN("download failed, push back to download queue and retry `", dl_item->dir);
             continue;
         }
+        
+        dl_span->SetAttribute("status", succ ? "success" : "failed");
+        dl_span->End();
+        
         LOG_DEBUG("finish downloading or no retry any more: `, retry_cnt: `", dl_item->dir,
                   dl_item->try_cnt);
         delete dl_item;
     }
 
     if (!dl_list.empty()) {
+        span->SetAttribute("unfinished_downloads", dl_list.size());
         LOG_INFO("DOWNLOAD THREAD EXITED in advance, delete dl_list.");
         while (!dl_list.empty()) {
             BKDL::BkDownload *dl_item = dl_list.front();
@@ -260,6 +417,7 @@ void bk_download_proc(std::list<BKDL::BkDownload *> &dl_list, uint64_t delay_sec
         }
     }
     LOG_INFO("BACKGROUND DOWNLOAD THREAD EXIT.");
+    span->End();
 }
 
 } // namespace BKDL

src/bk_download.h

@@ -18,6 +18,7 @@
 #include <string>
 #include <cstdint>
 #include <photon/fs/filesystem.h>
+#include "overlaybd/otel/tracer_common.h"
 
 class ImageFile;
 class ISwitchFile;