feat(logging): Add logging (#316)

* feat(logging): Add logging

* Add root logger. Abstraction on top of the debug module

* Switch to debug@2.6.9

* Remove noLogger

Author: manueliglesias

packages/aws-appsync/package.json

@@ -27,7 +27,7 @@
     "apollo-link-http": "1.3.1",
     "apollo-link-retry": "2.2.5",
     "aws-sdk": "2.329.0",
-    "debug": "^4.1.0",
+    "debug": "2.6.9",
     "graphql": "^0.11.7",
     "redux": "^3.7.2",
     "redux-thunk": "^2.2.0",

packages/aws-appsync/src/cache/offline-cache.ts

@@ -6,10 +6,14 @@
  * or in the "license" file accompanying this file. This file is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
  * KIND, express or implied. See the License for the specific language governing permissions and limitations under the License.
  */
+import { rootLogger } from "../utils";
 import { Cache } from 'apollo-cache';
 import { InMemoryCache, ApolloReducerConfig, defaultDataIdFromObject, NormalizedCacheObject } from 'apollo-cache-inmemory';
-import { Store } from 'redux';
+import { Store, AnyAction, Action } from 'redux';
 import { DeltaSyncState, DELTASYNC_KEY } from '../deltaSync';
+import { ThunkAction } from 'redux-thunk';
+
+const logger = rootLogger.extend('offline-cache');
 
 // Offline schema keys: Do not change in a non-backwards-compatible way
 export const NORMALIZED_CACHE_KEY = 'appsync';
@@ -74,14 +78,14 @@ export default class MyCache extends InMemoryCache {
             const { [NORMALIZED_CACHE_KEY]: normCache = {}, rehydrated = false } = this.store.getState();
             super.restore({ ...normCache });
             if (rehydrated) {
-                // console.log('Rehydrated! Cancelling subscription.');
+                logger('Rehydrated! Cancelling subscription.');
                 cancelSubscription();
             }
         });
     }
 
     restore(data: NormalizedCacheObject) {
-        this.store.dispatch(writeThunk(WRITE_CACHE_ACTION, data) as any);
+        boundWriteCache(this.store, data);
 
         super.restore(data);
         super.broadcastWatches();
@@ -99,14 +103,15 @@ export default class MyCache extends InMemoryCache {
         if (this.data && typeof (this.data as any).record === 'undefined') {
             // do not persist contents of a RecordingCache
             const data = super.extract(true);
-            this.store.dispatch(writeThunk(WRITE_CACHE_ACTION, data) as any);
+            boundWriteCache(this.store, data);
         } else {
-            // console.log('NO DISPATCH FOR RECORDINGCACHE')
+            logger('No dispatch for RecordingCache');
         }
     }
 
     reset() {
-        this.store.dispatch(writeThunk(WRITE_CACHE_ACTION, {}) as any);
+        logger('Resetting cache');
+        boundWriteCache(this.store, {});
 
         return super.reset();
     }
@@ -118,12 +123,18 @@ export default class MyCache extends InMemoryCache {
     }
 }
 
-const writeThunk = (type, payload) => (dispatch) => {
-    dispatch({
+const boundWriteCache = (store: Store<OfflineCache>, data: NormalizedCacheObject) => {
+    logger(`Dispatching ${WRITE_CACHE_ACTION}`, { data });
+
+    store.dispatch(writeThunk(WRITE_CACHE_ACTION, data) as any as Action);
+};
+
+const writeThunk:
+    (type: string, payload: any) => ThunkAction<Action, OfflineCache, null, AnyAction> =
+    (type, payload) => (dispatch, _getState) => dispatch({
         type,
         payload,
     });
-};
 
 export const reducer = () => ({
     [NORMALIZED_CACHE_KEY]: (state = {}, action) => {

packages/aws-appsync/src/deltaSync.ts

@@ -14,18 +14,17 @@ import AWSAppSyncClient, { OfflineCallback, SubscribeWithSyncOptions, QuerySyncO
 import { OfflineEffectConfig } from "./store";
 import { tryFunctionOrLogError, graphQLResultHasError, getMainDefinition, addTypenameToDocument } from "apollo-utilities";
 import { OperationVariables, MutationUpdaterFn } from "apollo-client";
-import { hash, getOperationFieldName } from "./utils";
+import { hash, getOperationFieldName, rootLogger } from "./utils";
 import { Observable, FetchResult } from "apollo-link";
 import { Subscription } from "apollo-client/util/Observable";
 import { DataProxy } from "apollo-cache";
-import debug from 'debug';
 import { SKIP_RETRY_KEY } from "./link/retry-link";
 import { DocumentNode, print, OperationDefinitionNode, FieldNode, ExecutionResult } from "graphql";
 import { getOpTypeFromOperationName, CacheOperationTypes, getUpdater, QueryWithVariables } from "./helpers/offline";
 import { boundSaveSnapshot, replaceUsingMap, EnqueuedMutationEffect, offlineEffectConfig as mutationsConfig } from "./link/offline-link";
 import { CONTROL_EVENTS_KEY } from "./link/subscription-handshake-link";
 
-const logger = debug('aws-appsync:deltasync');
+const logger = rootLogger.extend('deltasync');
 
 //#region Types
 type DeltaSyncUpdateLastSyncAction = AnyAction & {

packages/aws-appsync/src/helpers/offline.ts

@@ -12,7 +12,9 @@ import { ApolloClient, MutationOptions, SubscribeToMoreOptions, OperationVariabl
 import { DocumentNode, InputObjectTypeDefinitionNode, NamedTypeNode } from 'graphql';
 import AWSAppSyncClient from '../client';
 import { replaceUsingMap } from '../link';
-import { getOperationFieldName } from '../utils';
+import { getOperationFieldName, rootLogger } from '../utils';
+
+const logger = rootLogger.extend('offline-helper');
 
 export enum CacheOperationTypes {
     AUTO = 'auto',
@@ -298,7 +300,7 @@ const buildMutation = <T = OperationVariables>(
 
                 result = queryRead;
             } catch (err) {
-                console.warn('Skipping query', query, err.message);
+                logger('Skipping query', query, err.message);
 
                 return;
             }
@@ -358,7 +360,7 @@ const buildMutation = <T = OperationVariables>(
                     try {
                         data = proxy.readQuery({ query, variables: queryVars });
                     } catch (err) {
-                        console.warn('Skipping query', query, err.message);
+                        logger('Skipping query', query, err.message);
 
                         return;
                     }

packages/aws-appsync/src/link/offline-link.ts

@@ -17,7 +17,7 @@ import { NORMALIZED_CACHE_KEY, METADATA_KEY } from "../cache";
 import { AWSAppsyncGraphQLError } from "../types";
 import { Store } from "redux";
 import { OfflineCache, AppSyncMetadataState } from "../cache/offline-cache";
-import { isUuid, getOperationFieldName } from "../utils";
+import { isUuid, getOperationFieldName, rootLogger } from "../utils";
 import AWSAppSyncClient from "..";
 import { ApolloCache } from "apollo-cache";
 import { MutationUpdaterFn, MutationQueryReducersMap, ApolloError } from "apollo-client";
@@ -26,6 +26,8 @@ import { OfflineCallback } from "../client";
 import { SKIP_RETRY_KEY } from "./retry-link";
 import { OfflineEffectConfig } from "../store";
 
+const logger = rootLogger.extend('offline-link');
+
 const actions = {
     SAVE_SNAPSHOT: 'SAVE_SNAPSHOT',
     ENQUEUE: 'ENQUEUE_OFFLINE_MUTATION',
@@ -185,10 +187,6 @@ const enqueueMutation = <T>(operation: Operation, theStore: Store<OfflineCache>,
     return result;
 }
 
-interface CanBeSilenced<TCache> extends ApolloCache<TCache> {
-    silenceBroadcast?: boolean
-};
-
 const effect = async <TCache extends NormalizedCacheObject>(
     store: Store<OfflineCache>,
     client: AWSAppSyncClient<TCache>,
@@ -197,7 +195,6 @@ const effect = async <TCache extends NormalizedCacheObject>(
     callback: OfflineCallback,
 ): Promise<FetchResult<Record<string, any>, Record<string, any>>> => {
     const doIt = true;
-    const { cache }: { cache: CanBeSilenced<TCache> } = client;
     const {
         optimisticResponse: origOptimistic,
         operation: { variables: origVars, query: mutation, context },
@@ -232,6 +229,7 @@ const effect = async <TCache extends NormalizedCacheObject>(
         };
         const operation = buildOperationForLink.call(client.queryManager, mutation, variables, extraContext);
 
+        logger('Executing link', operation);
         execute(client.link, operation).subscribe({
             next: data => {
                 boundSaveServerId(store, optimisticResponse, data.data);
@@ -274,13 +272,16 @@ const effect = async <TCache extends NormalizedCacheObject>(
                         } = effect as EnqueuedMutationEffect<any>;
 
                         if (typeof update !== 'function') {
+                            logger('No update function for mutation', { document, variables });
                             return;
                         }
 
                         const optimisticResponse = replaceUsingMap({ ...origOptimisticResponse }, idsMap);
                         const result = { data: optimisticResponse };
 
                         if (fetchPolicy !== 'no-cache') {
+                            logger('Running update function for mutation', { document, variables });
+
                             dataStore.markMutationResult({
                                 mutationId: null,
                                 result,
@@ -334,7 +335,7 @@ const effect = async <TCache extends NormalizedCacheObject>(
                 }
             },
             error: err => {
-                // TODO: Undo cache updates?
+                logger('Error when executing link', err);
 
                 reject(err);
             }
@@ -450,14 +451,10 @@ const discard = (callback: OfflineCallback, error, action, retries) => {
 
     if (discardResult) {
         // Call global error callback or observer
-        try {
-            if (typeof callback === 'function') {
-                tryFunctionOrLogError(() => {
-                    callback({ error }, null);
-                });
-            }
-        } catch (error) {
-            // TODO: warn
+        if (typeof callback === 'function') {
+            tryFunctionOrLogError(() => {
+                callback({ error }, null);
+            });
         }
     }
 
@@ -468,15 +465,15 @@ const _discard = (error, action: OfflineAction, retries) => {
     const { graphQLErrors = [] }: { graphQLErrors: AWSAppsyncGraphQLError[] } = error;
 
     if (graphQLErrors.length) {
-        // console.error('Discarding action.', action, graphQLErrors);
+        logger('Discarding action.', action, graphQLErrors);
 
         return true;
     } else {
         const { networkError: { graphQLErrors = [] } = { graphQLErrors: [] } } = error;
         const appSyncClientError = graphQLErrors.find(err => err.errorType && err.errorType.startsWith('AWSAppSyncClient:'));
 
         if (appSyncClientError) {
-            // console.error('Discarding action.', action, appSyncClientError);
+            logger('Discarding action.', action, appSyncClientError);
 
             return true;
         }

packages/aws-appsync/src/link/subscription-handshake-link.ts

@@ -8,11 +8,15 @@
  */
 import { ApolloLink, Observable, Operation, FetchResult } from "apollo-link";
 
+import { rootLogger } from "../utils";
 import * as Paho from '../vendor/paho-mqtt';
 import { ApolloError } from "apollo-client";
 import { FieldNode } from "graphql";
 import { getMainDefinition } from "apollo-utilities";
 
+const logger = rootLogger.extend('subscriptions');
+const mqttLogger = logger.extend('mqtt');
+
 type SubscriptionExtension = {
     mqttConnections: MqttConnectionInfo[],
     newSubscriptions: NewSubscriptions,
@@ -161,7 +165,7 @@ export class SubscriptionHandshakeLink extends ApolloLink {
         const { client: clientId, url, topics } = connectionInfo;
         const client: any = new Paho.Client(url, clientId);
 
-        // client.trace = console.log.bind(null, clientId);
+        client.trace = mqttLogger.bind(null, clientId);
         client.onConnectionLost = ({ errorCode, ...args }) => {
             if (errorCode !== 0) {
                 topics.forEach(t => {
@@ -224,14 +228,16 @@ export class SubscriptionHandshakeLink extends ApolloLink {
             parsedMessage.data || {}
         );
 
+        logger('Message received', { data, topic, observers });
+
         observers.forEach(observer => {
             try {
                 observer.next({
                     ...parsedMessage,
                     ...{ data },
                 })
             } catch (err) {
-                // console.error(err);
+                logger(err);
             }
         });
     }

packages/aws-appsync/src/store.ts

@@ -6,6 +6,7 @@
  * or in the "license" file accompanying this file. This file is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
  * KIND, express or implied. See the License for the specific language governing permissions and limitations under the License.
  */
+import { rootLogger } from "./utils";
 import { applyMiddleware, createStore, compose, combineReducers, Store, Reducer, AnyAction, ReducersMapObject } from 'redux';
 import { offline } from '@redux-offline/redux-offline';
 import defaultOfflineConfig from '@redux-offline/redux-offline/lib/defaults';
@@ -23,13 +24,16 @@ import { Observable } from 'apollo-link';
 
 const { detectNetwork } = defaultOfflineConfig;
 
+const logger = rootLogger.extend('store');
+
 const newStore = <TCacheShape extends NormalizedCacheObject>(
     clientGetter: () => AWSAppSyncClient<TCacheShape> = () => null,
     persistCallback = () => null,
     dataIdFromObject: (obj) => string | null,
     storage: any,
     callback: OfflineCallback = () => { },
 ): Store<any> => {
+    logger('Creating store');
 
     const store = createStore(
         combineReducers({
@@ -50,7 +54,11 @@ const newStore = <TCacheShape extends NormalizedCacheObject>(
             offline({
                 ...defaultOfflineConfig,
                 retry: getEffectDelay,
-                persistCallback,
+                persistCallback: () => {
+                    logger('Storage ready');
+
+                    persistCallback();
+                },
                 persistOptions: {
                     ...(storage && { storage }),
                     whitelist: [
@@ -115,17 +123,24 @@ const effect = async (effect, action: OfflineAction, store, clientGetter, callba
     });
 
     if (config && config.effect) {
+        logger(`Executing effect for ${action.type}`);
+
         return config.effect(store, clientGetter, effect, action, callback, observable);
     }
+
+    logger(`No effect found for ${action.type}`);
 };
 
 const discard = (callback, error, action, retries) => {
     const { discard } = offlineEffectsConfigs[action.type];
 
     if (discard) {
+        logger(`Executing discard for ${action.type}`, discard);
+
         return discard(callback, error, action, retries);
     }
 
+    logger(`No custom discard found for ${action.type}. Discarding effect.`);
     return true;
 };
 

packages/aws-appsync/src/utils/index.ts

@@ -21,3 +21,5 @@ export const getOperationFieldName = (operation: DocumentNode): string => result
 );
 
 export const hash = (src: any) => crypto.createHash('sha256').update(src || {}, 'utf8').digest('hex') as string;
+
+export { default as rootLogger } from './logger';

packages/aws-appsync/src/utils/logger.ts

@@ -0,0 +1,19 @@
+import debug from 'debug';
+
+export type Logger = Function & {
+    extend(category: string): Logger;
+};
+
+const debugLogger = debug('aws-appsync') as Logger;
+
+const extend = function (category = '') {
+    const newCategory = category ? [...this.namespace.split(':'), category].join(':') : this.namespace;
+
+    const result = debug(newCategory);
+    result.extend = extend.bind(result);
+
+    return result;
+};
+debugLogger.extend = extend.bind(debugLogger);
+
+export default debugLogger;

yarn.lock

@@ -1774,12 +1774,6 @@ debug@^3.1.0:
   dependencies:
     ms "^2.1.1"
 
-debug@^4.1.0:
-  version "4.1.0"
-  resolved "https://registry.yarnpkg.com/debug/-/debug-4.1.0.tgz#373687bffa678b38b1cd91f861b63850035ddc87"
-  dependencies:
-    ms "^2.1.1"
-
 debug@~2.2.0:
   version "2.2.0"
   resolved "http://registry.npmjs.org/debug/-/debug-2.2.0.tgz#f87057e995b1a1f6ae6a4960664137bc56f039da"