CronetLogger: add logging calls to native cronet code

Logging calls happen respectively after the creation of the native
CronetEngine and before calling Listener#onRequestFinished.

Currently:
* All engine creation logging calls are reported as originating
  from statically linked/bundled Cronet
* Bidirectional streams don't report traffic info events

Bug: b:226554121

Change-Id: Iaa9ce6047851f5116c25ca760f8788d08753959d
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/3672897
Reviewed-by: Richard Coles <torne@chromium.org>
Commit-Queue: Stefano Duo <stefanoduo@google.com>
Cr-Commit-Position: refs/heads/main@{#1017235}

components/cronet/android/java/src/org/chromium/net/impl/CronetLogger.java

@@ -300,5 +300,11 @@ public int getBuildVersion() {
         public int getPatchVersion() {
             return mPatchVersion;
         }
+
+        @Override
+        public String toString() {
+            return "" + mMajorVersion + "." + mMinorVersion + "." + mBuildVersion + "."
+                    + mPatchVersion;
+        }
     }
 }

components/cronet/android/java/src/org/chromium/net/impl/CronetUrlRequest.java

@@ -5,8 +5,10 @@
 package org.chromium.net.impl;
 
 import android.net.Network;
+import android.os.Build;
 
 import androidx.annotation.Nullable;
+import androidx.annotation.RequiresApi;
 import androidx.annotation.VisibleForTesting;
 
 import org.chromium.base.Log;
@@ -24,11 +26,14 @@
 import org.chromium.net.RequestPriority;
 import org.chromium.net.UploadDataProvider;
 import org.chromium.net.UrlRequest;
+import org.chromium.net.impl.CronetLogger.CronetTrafficInfo;
 
 import java.nio.ByteBuffer;
+import java.time.Duration;
 import java.util.AbstractMap;
 import java.util.ArrayList;
 import java.util.Collection;
+import java.util.Collections;
 import java.util.List;
 import java.util.Map;
 import java.util.concurrent.Executor;
@@ -99,6 +104,7 @@ public final class CronetUrlRequest extends UrlRequestBase {
     private final int mTrafficStatsUid;
     private final VersionSafeCallbacks.RequestFinishedInfoListener mRequestFinishedListener;
     private final long mNetworkHandle;
+    private final int mCronetEngineID;
 
     private CronetUploadDataStream mUploadDataStream;
 
@@ -120,7 +126,8 @@ public final class CronetUrlRequest extends UrlRequestBase {
     @GuardedBy("mUrlRequestAdapterLock")
     private Runnable mOnDestroyedCallbackForTesting;
 
-    private static final class HeadersList extends ArrayList<Map.Entry<String, String>> {}
+    @VisibleForTesting
+    static final class HeadersList extends ArrayList<Map.Entry<String, String>> {}
 
     private final class OnReadCompletedRunnable implements Runnable {
         // Buffer passed back from current invocation of onReadCompleted.
@@ -165,6 +172,7 @@ public void run() {
 
         mAllowDirectExecutor = allowDirectExecutor;
         mRequestContext = requestContext;
+        mCronetEngineID = requestContext.getCronetEngineId();
         mInitialUrl = url;
         mUrlChain.add(url);
         mPriority = convertRequestPriority(priority);
@@ -443,6 +451,44 @@ private static int convertIdempotency(int idempotency) {
         }
     }
 
+    /**
+     * Estimates the byte size of the headers in their on-wire format.
+     * We are not really interested in their specific size but something which is close enough.
+     */
+    @VisibleForTesting
+    static long estimateHeadersSizeInBytes(Map<String, List<String>> headers) {
+        if (headers == null) return 0;
+
+        long responseHeaderSizeInBytes = 0;
+        for (Map.Entry<String, List<String>> entry : headers.entrySet()) {
+            String key = entry.getKey();
+            if (key != null) responseHeaderSizeInBytes += key.length();
+            if (entry.getValue() == null) continue;
+
+            for (String content : entry.getValue()) {
+                responseHeaderSizeInBytes += content.length();
+            }
+        }
+        return responseHeaderSizeInBytes;
+    }
+
+    /**
+     * Estimates the byte size of the headers in their on-wire format.
+     * We are not really interested in their specific size but something which is close enough.
+     */
+    @VisibleForTesting
+    static long estimateHeadersSizeInBytes(HeadersList headers) {
+        if (headers == null) return 0;
+        long responseHeaderSizeInBytes = 0;
+        for (Map.Entry<String, String> entry : headers) {
+            String key = entry.getKey();
+            if (key != null) responseHeaderSizeInBytes += key.length();
+            String value = entry.getValue();
+            if (value != null) responseHeaderSizeInBytes += entry.getValue().length();
+        }
+        return responseHeaderSizeInBytes;
+    }
+
     private UrlResponseInfoImpl prepareResponseInfoOnNetworkThread(int httpStatusCode,
             String httpStatusText, String[] headers, boolean wasCached, String negotiatedProtocol,
             String proxyServer, long receivedByteCount) {
@@ -829,10 +875,95 @@ private int mapUrlRequestErrorToApiErrorCode(int errorCode) {
         }
     }
 
+    private static long parseContentLengthString(String contentLength) {
+        try {
+            return Long.parseLong(contentLength);
+        } catch (NumberFormatException e) {
+            return 0;
+        }
+    }
+
+    /**
+     * Builds the {@link CronetTrafficInfo} associated to this request internal state.
+     * This helper methods makes strong assumptions about the state of the request. For this reason
+     * it should only be called within {@link CronetUrlRequest#maybeReportMetrics} where these
+     * assumptions are guaranteed to be true.
+     * @return the {@link CronetTrafficInfo} associated to this request internal state
+     */
+    @RequiresApi(Build.VERSION_CODES.O)
+    private CronetTrafficInfo buildCronetTrafficInfo() {
+        assert mMetrics != null;
+        assert mRequestHeaders != null;
+
+        // Most of the CronetTrafficInfo fields have similar names/semantics. To avoid bugs due to
+        // typos everything is final, this means that things have to initialized through an if/else.
+        final Map<String, List<String>> responseHeaders;
+        final String negotiatedProtocol;
+        final int httpStatusCode;
+        if (mResponseInfo != null) {
+            responseHeaders = mResponseInfo.getAllHeaders();
+            negotiatedProtocol = mResponseInfo.getNegotiatedProtocol();
+            httpStatusCode = mResponseInfo.getHttpStatusCode();
+        } else {
+            responseHeaders = Collections.emptyMap();
+            negotiatedProtocol = "";
+            httpStatusCode = 0;
+        }
+
+        // TODO(stefanoduo): A better approach might be keeping track of the total length of an
+        // upload and use that value as the request body size instead.
+        final long requestTotalSizeInBytes = mMetrics.getSentByteCount();
+        final long requestHeaderSizeInBytes = estimateHeadersSizeInBytes(mRequestHeaders);
+        final long requestBodySizeInBytes = requestTotalSizeInBytes - requestHeaderSizeInBytes;
+
+        final long responseTotalSizeInBytes = mMetrics.getReceivedByteCount();
+        final long responseBodySizeInBytes;
+        final long responseHeaderSizeInBytes;
+        // Content-Length is not mandatory, if missing approximate it by using the response headers
+        // size instead.
+        if (responseHeaders.containsKey("Content-Length")) {
+            responseBodySizeInBytes =
+                    parseContentLengthString(responseHeaders.get("Content-Length").get(0));
+            responseHeaderSizeInBytes = responseTotalSizeInBytes - responseBodySizeInBytes;
+        } else {
+            responseHeaderSizeInBytes = estimateHeadersSizeInBytes(responseHeaders);
+            responseBodySizeInBytes = responseTotalSizeInBytes - responseHeaderSizeInBytes;
+        }
+
+        final Duration headersLatency;
+        if (mMetrics.getRequestStart() != null && mMetrics.getResponseStart() != null) {
+            headersLatency = Duration.ofMillis(
+                    mMetrics.getResponseStart().getTime() - mMetrics.getRequestStart().getTime());
+        } else {
+            headersLatency = Duration.ofSeconds(0);
+        }
+
+        final Duration totalLatency;
+        if (mMetrics.getRequestStart() != null && mMetrics.getRequestEnd() != null) {
+            totalLatency = Duration.ofMillis(
+                    mMetrics.getRequestEnd().getTime() - mMetrics.getRequestStart().getTime());
+        } else {
+            totalLatency = Duration.ofSeconds(0);
+        }
+
+        return new CronetTrafficInfo(requestHeaderSizeInBytes, requestBodySizeInBytes,
+                responseHeaderSizeInBytes, responseBodySizeInBytes, httpStatusCode, headersLatency,
+                totalLatency, negotiatedProtocol,
+                // TODO(stefanoduo): Possibly retrieve this by extending NetErrorDetails.
+                false, // wasConnectionMigrationAttempted
+                false // didConnectionMigrationSucceed
+        );
+    }
+
     // Maybe report metrics. This method should only be called on Callback's executor thread and
     // after Callback's onSucceeded, onFailed and onCanceled.
     private void maybeReportMetrics() {
         if (mMetrics != null) {
+            if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.O) {
+                CronetLogger logger = CronetLoggerFactory.createLogger();
+                logger.logCronetTrafficInfo(mCronetEngineID, buildCronetTrafficInfo());
+            }
+
             final RequestFinishedInfo requestInfo = new RequestFinishedInfoImpl(mInitialUrl,
                     mRequestAnnotations, mMetrics, mFinishedReason, mResponseInfo, mException);
             mRequestContext.reportRequestFinished(requestInfo);

components/cronet/android/java/src/org/chromium/net/impl/CronetUrlRequestContext.java

@@ -27,6 +27,9 @@
 import org.chromium.net.RequestFinishedInfo;
 import org.chromium.net.RttThroughputValues;
 import org.chromium.net.UrlRequest;
+import org.chromium.net.impl.CronetLogger.CronetEngineBuilderInfo;
+import org.chromium.net.impl.CronetLogger.CronetSource;
+import org.chromium.net.impl.CronetLogger.CronetVersion;
 import org.chromium.net.urlconnection.CronetHttpURLConnection;
 import org.chromium.net.urlconnection.CronetURLStreamHandlerFactory;
 
@@ -160,8 +163,15 @@ public class CronetUrlRequestContext extends CronetEngineBase {
     /** If not null, the network to be used for requests that do not explicitly specify one. **/
     private @Nullable Network mNetwork;
 
+    private final int mCronetEngineId;
+
+    int getCronetEngineId() {
+        return mCronetEngineId;
+    }
+
     @UsedByReflection("CronetEngine.java")
     public CronetUrlRequestContext(final CronetEngineBuilderImpl builder) {
+        mCronetEngineId = hashCode();
         mRttListenerList.disableThreadAsserts();
         mThroughputListenerList.disableThreadAsserts();
         mNetworkQualityEstimatorEnabled = builder.networkQualityEstimatorEnabled();
@@ -187,6 +197,15 @@ public CronetUrlRequestContext(final CronetEngineBuilderImpl builder) {
                 throw new NullPointerException("Context Adapter creation failed.");
             }
         }
+        CronetLogger logger = CronetLoggerFactory.createLogger();
+        // getVersionString()'s output looks like "Cronet/w.x.y.z@hash". CronetVersion only cares
+        // about the "w.x.y.z" bit.
+        String version = getVersionString();
+        version = version.split("/")[1];
+        version = version.split("@")[0];
+        // TODO(stefanoduo): Correctly generate the CronetSource parameter.
+        logger.logCronetEngineCreation(getCronetEngineId(), new CronetEngineBuilderInfo(builder),
+                new CronetVersion(version), CronetSource.CRONET_SOURCE_STATICALLY_LINKED);
 
         // Init native Chromium URLRequestContext on init thread.
         CronetLibraryLoader.postToInitThread(new Runnable() {