chore: improve logging (#82)

Co-authored-by: David Bosschaert <bosschae@adobe.com>

Author: kptdobe

src/edge.js

@@ -139,49 +139,56 @@ export async function handleApiRequest(request, env) {
 
     if (!initialReq.ok && initialReq.status !== 404) {
       // eslint-disable-next-line no-console
-      console.log(`${initialReq.status} - ${initialReq.statusText}`);
+      console.log(`Unable to get resource ${docName}: ${initialReq.status} - ${initialReq.statusText}`);
       return new Response('unable to get resource', { status: initialReq.status });
     }
 
     const daActions = initialReq.headers.get('X-da-actions') ?? '';
     [, authActions] = daActions.split('=');
   } catch (err) {
     // eslint-disable-next-line no-console
-    console.log(err);
+    console.error(`Unable to handle API request ${docName}`, err);
     return new Response('unable to get resource', { status: 500 });
   }
 
-  const timingBeforeDocRoomGet = Date.now();
-  // Each Durable Object has a 256-bit unique ID. Route the request based on the path.
-  const id = env.rooms.idFromName(docName);
-
-  // Get the Durable Object stub for this room! The stub is a client object that can be used
-  // to send messages to the remote Durable Object instance. The stub is returned immediately;
-  // there is no need to await it. This is important because you would not want to wait for
-  // a network round trip before you could start sending requests. Since Durable Objects are
-  // created on-demand when the ID is first used, there's nothing to wait for anyway; we know
-  // an object will be available somewhere to receive our requests.
-  const roomObject = env.rooms.get(id);
-  const timingDocRoomGetDuration = Date.now() - timingBeforeDocRoomGet;
+  try {
+    const timingBeforeDocRoomGet = Date.now();
+    // Each Durable Object has a 256-bit unique ID. Route the request based on the path.
+    const id = env.rooms.idFromName(docName);
+
+    // Get the Durable Object stub for this room! The stub is a client object that can be used
+    // to send messages to the remote Durable Object instance. The stub is returned immediately;
+    // there is no need to await it. This is important because you would not want to wait for
+    // a network round trip before you could start sending requests. Since Durable Objects are
+    // created on-demand when the ID is first used, there's nothing to wait for anyway; we know
+    // an object will be available somewhere to receive our requests.
+    const roomObject = env.rooms.get(id);
+    const timingDocRoomGetDuration = Date.now() - timingBeforeDocRoomGet;
 
-  // eslint-disable-next-line no-console
-  console.log(`FETCHING: ${docName} ${id}`);
-
-  const headers = [...request.headers,
-    ['X-collab-room', docName],
-    ['X-timing-start', timingStartTime],
-    ['X-timing-da-admin-head-duration', timingDaAdminHeadDuration],
-    ['X-timing-docroom-get-duration', timingDocRoomGetDuration],
-    ['X-auth-actions', authActions],
-  ];
-  if (auth) {
-    headers.push(['Authorization', auth]);
+    // eslint-disable-next-line no-console
+    console.log(`Fetching: ${docName} ${id}`);
+
+    const headers = [...request.headers,
+      ['X-collab-room', docName],
+      ['X-timing-start', timingStartTime],
+      ['X-timing-da-admin-head-duration', timingDaAdminHeadDuration],
+      ['X-timing-docroom-get-duration', timingDocRoomGetDuration],
+      ['X-auth-actions', authActions],
+    ];
+    if (auth) {
+      headers.push(['Authorization', auth]);
+    }
+    const req = new Request(new URL(docName), { headers });
+    // Send the request to the Durable Object. The `fetch()` method of a Durable Object stub has the
+    // same signature as the global `fetch()` function, but the request is always sent to the
+    // object, regardless of the hostname in the request's URL.
+    const res = await roomObject.fetch(req);
+    return res;
+  } catch (err) {
+    // eslint-disable-next-line no-console
+    console.error(`Error fetching the doc from the room ${docName}`, err);
+    return new Response('unable to get resource', { status: 500 });
   }
-  const req = new Request(new URL(docName), { headers });
-  // Send the request to the Durable Object. The `fetch()` method of a Durable Object stub has the
-  // same signature as the global `fetch()` function, but the request is always sent to the
-  // object, regardless of the hostname in the request's URL.
-  return roomObject.fetch(req);
 }
 
 // In modules-syntax workers, we use `export default` to export our script's main event handlers.
@@ -311,7 +318,7 @@ export class DocRoom {
       webSocket.readOnly = true;
     }
     // eslint-disable-next-line no-console
-    console.log(`setupWSConnection ${docName} with auth(${webSocket.auth
+    console.log(`Setting up WSConnection for ${docName} with auth(${webSocket.auth
       ? webSocket.auth.substring(0, webSocket.auth.indexOf(' ')) : 'none'})`);
     const timingData = await setupWSConnection(webSocket, docName, this.env, this.storage);
     return timingData;

src/shareddoc.js

@@ -87,6 +87,8 @@ export const readState = async (docName, storage) => {
   }
 
   if (stored.has('docstore')) {
+    // eslint-disable-next-line no-console
+    console.log('Document found in persistence');
     return stored.get('docstore');
   }
 
@@ -100,6 +102,8 @@ export const readState = async (docName, storage) => {
       data.push(chunk[j]);
     }
   }
+  // eslint-disable-next-line no-console
+  console.log('Document data read');
   return new Uint8Array(data);
 };
 
@@ -182,7 +186,7 @@ export const persistence = {
       return null;
     } else {
       // eslint-disable-next-line no-console
-      console.log(`unable to get resource: ${initialReq.status} - ${initialReq.statusText}`);
+      console.error(`Unable to get resource from da-admin: ${initialReq.status} - ${initialReq.statusText}`);
       throw new Error(`unable to get resource - status: ${initialReq.status}`);
     }
   },
@@ -247,14 +251,12 @@ export const persistence = {
           closeAll = (status === 401 || status === 403);
           throw new Error(`${status} - ${statusText}`);
         }
-        // eslint-disable-next-line no-console
-        console.log(content);
 
         return content;
       }
     } catch (err) {
       // eslint-disable-next-line no-console
-      console.error(err);
+      console.error('Failed to update document', err);
       showError(ydoc, err);
     }
     if (closeAll) {
@@ -320,7 +322,7 @@ export const persistence = {
       }
     } catch (error) {
       // eslint-disable-next-line no-console
-      console.log('Problem restoring state from worker storage', error);
+      console.error('Problem restoring state from worker storage', error);
       showError(ydoc, error);
     }
 
@@ -342,7 +344,7 @@ export const persistence = {
               console.log('Restored from da-admin', docName);
             } catch (error) {
               // eslint-disable-next-line no-console
-              console.log('Problem restoring state from da-admin', error);
+              console.error('Problem restoring state from da-admin', error);
               showError(ydoc, error);
             }
           });
@@ -507,7 +509,7 @@ export const messageListener = (conn, doc, message) => {
     }
   } catch (err) {
     // eslint-disable-next-line no-console
-    console.error(err);
+    console.error('Error in messageListener', err);
     showError(doc, err);
   }
 };