Bug fix + Added extensive traces for downloading of contexts for #1419

CHANGES_NEXT_RELEASE

@@ -1 +1,3 @@
 Fixed issues:
+  * #1419 - Fixed a bug in the cleanup of the "URL being downloaded list" - not being cleaned up in case of an error
+  * #280  - Added extensive logging for downloading of contexts

src/lib/logMsg/traceLevels.h

@@ -89,6 +89,7 @@ typedef enum TraceLevels
   LmtContexts = 80,                    // Contexts
   LmtContextTree,                      // Context Tree
   LmtContextCache,                     // Context Cache
+  LmtContextDownload,                  // Context Download
   LmtCoreContext,                      // Core Context
 
   // GeoJSON

src/lib/orionld/common/orionldRequestSend.cpp

@@ -44,6 +44,8 @@ static size_t writeCallback(void* contents, size_t size, size_t members, void* u
   OrionldResponseBuffer*  rBufP        = (OrionldResponseBuffer*) userP;
   int                     xtraBytes    = 512;
 
+  LM_T(LmtCurl, ("CURL: got %d bytes of payload body: %s", bytesToCopy, contents));
+
   if (bytesToCopy + rBufP->used >= rBufP->size)
   {
     if (rBufP->buf == rBufP->internalBuffer)

src/lib/orionld/context/orionldContextFromUrl.cpp

@@ -74,19 +74,44 @@ bool contextDownloadListLookup(const char* url)
 {
   StringListItem* itemP = contextDownloadList;
 
+  LM_T(LmtContextDownload, ("Looking for context URL '%s'", url));
   while (itemP != NULL)
   {
+    LM_T(LmtContextDownload, ("Comparing existing '%s' to wanted '%s'", itemP->name, url));
     if (strcmp(itemP->name, url) == 0)
+    {
+      LM_T(LmtContextDownload, ("Found a match: '%s'", url));
       return true;
+    }
 
     itemP = itemP->next;
   }
 
+  LM_T(LmtContextDownload, ("Found no match for '%s'", url));
   return false;
 }
 
 
 
+// -----------------------------------------------------------------------------
+//
+// contextDownloadListDebug -
+//
+static void contextDownloadListDebug(const char* what)
+{
+  LM_T(LmtContextDownload, ("contextDownloadList (%s)", what));
+  LM_T(LmtContextDownload, ("----------------------------------------------------"));
+
+  for (StringListItem* iterP = contextDownloadList; iterP != NULL; iterP = iterP->next)
+  {
+    LM_T(LmtContextDownload, ("  o %s", iterP->name));
+  }
+
+  LM_T(LmtContextDownload, ("----------------------------------------------------"));
+}
+
+
+
 // -----------------------------------------------------------------------------
 //
 // contextDownloadListAdd - add a URL to the list
@@ -95,9 +120,11 @@ void contextDownloadListAdd(const char* url)
 {
   StringListItem* itemP = (StringListItem*) malloc(sizeof(StringListItem));
 
+  LM_T(LmtContextDownload, ("Adding '%s' to contextDownloadList", url));
   strncpy(itemP->name, url, sizeof(itemP->name) - 1);
   itemP->next = contextDownloadList;
   contextDownloadList = itemP;
+  contextDownloadListDebug("after item added");
 }
 
 
@@ -112,6 +139,8 @@ void contextDownloadListRemove(const char* url)
   StringListItem* prevP = NULL;
   StringListItem* itemP = NULL;
 
+  LM_T(LmtContextDownload, ("Removing '%s' from contextDownloadList", url));
+
   while (iterP != NULL)
   {
     if (strcmp(iterP->name, url) == 0)
@@ -125,23 +154,31 @@ void contextDownloadListRemove(const char* url)
   }
 
   if (itemP == NULL)  // Not found!
+  {
+    LM_T(LmtContextDownload, ("Cannot find '%s' in contextDownloadList", url));
     return;
+  }
 
   if (prevP == NULL)  // Found as the first item of the list
   {
+    LM_T(LmtContextDownload, ("Removing '%s' as first item in contextDownloadList", url));
     contextDownloadList = itemP->next;
     free(itemP);
   }
   else if (itemP->next == NULL)  // Found as the last item of the list
   {
+    LM_T(LmtContextDownload, ("Removing '%s' as last item in contextDownloadList", url));
     prevP->next = NULL;
     free(itemP);
   }
   else  // Found in the middle of the list
   {
+    LM_T(LmtContextDownload, ("Removing '%s' as middle item in contextDownloadList", url));
     prevP->next = itemP->next;
     free(itemP);
   }
+
+  contextDownloadListDebug("after item removal");
 }
 
 
@@ -178,16 +215,24 @@ static OrionldContext* contextCacheWait(char* url)
   int             sleepTime = 0;
   OrionldContext* contextP;
 
+  LM_T(LmtContextDownload, ("Awaiting a context download by other (URL: %s)", url));
+
   while (sleepTime < 3000000)  // 3 secs - 3 million microsecs ... CLI param?
   {
     usleep(20000);  // sleep 20 millisecs ... CLI param?
+    LM_T(LmtContextDownload, ("Awaiting context download: looking up context '%s'", url));
     contextP = orionldContextCacheLookup(url);
     if (contextP != NULL)
+    {
+      LM_T(LmtContextDownload, ("Got it! (%s)", url));
       return contextP;
+    }
+    LM_T(LmtContextDownload, ("Still not there (%s)", url));
     sleepTime += 20000;
   }
+  LM_T(LmtContextDownload, ("Timeout during download of an @context (%s)", url));
 
-  // The wait timed out - assuming the URL is invalid, this a "400 Bad Request"
+  // The wait timed out
   orionldError(OrionldInternalError, "Timeout during download of an @context", url, 504);
   return NULL;
 }
@@ -200,10 +245,15 @@ static OrionldContext* contextCacheWait(char* url)
 //
 OrionldContext* orionldContextFromUrl(char* url, char* id)
 {
+  LM_T(LmtContextDownload, ("Downloading a context URL: '%s'", url));
+
   OrionldContext* contextP = orionldContextCacheLookup(url);
 
   if (contextP != NULL)
+  {
+    LM_T(LmtContextDownload, ("Found already downloaded URL '%s'", url));
     return contextP;
+  }
 
   //
   // Make sure the context isn't already being downloaded
@@ -228,7 +278,9 @@ OrionldContext* orionldContextFromUrl(char* url, char* id)
     // Not there, so, we'll download it
     // First take the 'download semaphore'
     //
+    LM_T(LmtContextDownload, ("The context '%s' is not downloading, getting the downloadList semaphore", url));
     sem_wait(&contextDownloadListSem);
+    LM_T(LmtContextDownload, ("Got the downloadList semaphore for '%s'", url));
 
     //
     // OK - got the semaphore - but, did I have to wait?
@@ -237,49 +289,57 @@ OrionldContext* orionldContextFromUrl(char* url, char* id)
     // If the URL is in 'contextDownloadList' then somebody else took the semaphore before me
     // and started downloading.
     //
+    LM_T(LmtContextDownload, ("Looking up '%s' again, in case I got the semaphore late", url));
     urlDownloading = contextDownloadListLookup(url);
     if (urlDownloading == false)
+    {
+      LM_T(LmtContextDownload, ("The context '%s' is not downloading by other - will be downloaded here", url));
       contextDownloadListAdd(url);  // CASE 1: Mark the URL as being downloading
+    }
 
+    LM_T(LmtContextDownload, ("Giving back the downloadList semaphore for '%s'", url));
     sem_post(&contextDownloadListSem);
 
     if (urlDownloading == true)  // If somebody has taken the semaphore before me and is downloading the context - I'll have to wait
+    {
+      LM_T(LmtContextDownload, ("The context '%s' is downloading by other - I wait until it's done", url));
       return contextCacheWait(url);  // CASE 2 - another thread has downloaded the context
+    }
 
     // CASE 1 - the context will be downloaded
   }
   else
+  {
+    LM_T(LmtContextDownload, ("The context '%s' is downloading by other - I wait until it's done", url));
     return contextCacheWait(url);  // CASE 3 - another thread has downloaded the context
+  }
 
+  LM_T(LmtContextDownload, ("Downloading the context '%s' and adding it to the context cache", url));
   char* buffer = orionldContextDownload(url);  // orionldContextDownload fills in ProblemDetails
-  if (buffer == NULL)
-    return NULL;
 
-  LM_T(LmtCoreContext, ("Downloaded the conext '%s'", url));
-  contextP = orionldContextFromBuffer(url, OrionldContextDownloaded, id, buffer);
-  if (contextP == NULL)
+  if (buffer != NULL)  // All OK
   {
-    //
-    // Uncomfortable problem here ...
-    // The downloaded @context is erroneous and cannot be used.
-    // The response to the request indicates this fact, but, if the client
-    // insists on trying to use the context (without fixing it), the broker will download it over and over again.
-    // Still, I believe this is the best solution.
-    //
-    LM_E(("Context Error (%s: %s)", orionldState.pd.title, orionldState.pd.detail));
-    contextDownloadListRemove(url);
-    return NULL;  // Parse Error?
+    LM_T(LmtCoreContext, ("Downloaded the context '%s'", url));
+    contextP = orionldContextFromBuffer(url, OrionldContextDownloaded, id, buffer);
+    if (contextP == NULL)
+      LM_E(("Context Error (%s: %s)", orionldState.pd.title, orionldState.pd.detail));
   }
+  else
+    LM_E(("Context Error (%s: %s)", orionldState.pd.title, orionldState.pd.detail));
 
-  contextP->origin    = OrionldContextDownloaded;
-  contextP->createdAt = orionldState.requestTime;
-  contextP->usedAt    = orionldState.requestTime;
+  if (contextP != NULL)
+  {
+    contextP->origin    = OrionldContextDownloaded;
+    contextP->createdAt = orionldState.requestTime;
+    contextP->usedAt    = orionldState.requestTime;
+
+    orionldContextCachePersist(contextP);
+  }
 
   // Remove the 'url' from the contextDownloadList and persist it to DB
   sem_wait(&contextDownloadListSem);
   contextDownloadListRemove(url);
   sem_post(&contextDownloadListSem);
-  orionldContextCachePersist(contextP);
 
   return contextP;
 }