changeset 2307:1606353a9fcb

- Whenever possible, mention the currently used handle in error/debug messages, to aid debugging of concurrent requests

--- a/src/neon/neon.c	Sun Jan 13 17:33:47 2008 +0100
+++ b/src/neon/neon.c	Sun Jan 13 17:57:08 2008 +0100
@@ -130,6 +130,8 @@
 
     _ENTER;
 
+    _DEBUG("<%p> freeing handle", handle);
+
     ne_uri_free(h->purl);
     destroy_rb(&h->rb);
     if (NULL != h->icy_metadata.stream_name) {
@@ -563,11 +565,11 @@
 
     if (use_proxy) {
         if (FALSE == aud_cfg_db_get_string(db, NULL, "proxy_host", &proxy_host)) {
-            _ERROR("Could not read proxy host, disabling proxy use");
+            _ERROR("<%p> Could not read proxy host, disabling proxy use", handle);
             use_proxy = FALSE;
         }
         if (FALSE == aud_cfg_db_get_string(db, NULL, "proxy_port", &proxy_port_s)) {
-            _ERROR("Could not read proxy port, disabling proxy use");
+            _ERROR("<%p> Could not read proxy port, disabling proxy use", handle);
             use_proxy = FALSE;
         }
         proxy_port = strtoul(proxy_port_s, &endptr, 10);
@@ -575,7 +577,7 @@
             /*
              * Invalid data
              */
-            _ERROR("Invalid proxy port, disabling proxy use");
+            _ERROR("<%p> Invalid proxy port, disabling proxy use", handle);
             use_proxy = FALSE;
         }
     }
@@ -583,9 +585,9 @@
 
     handle->redircount = 0;
 
-    _DEBUG("Parsing URL");
+    _DEBUG("<%p> Parsing URL", handle);
     if (0 != ne_uri_parse(handle->url, handle->purl)) {
-        _ERROR("Could not parse URL '%s'", handle->url);
+        _ERROR("<%p> Could not parse URL '%s'", handle, handle->url);
         _LEAVE -1;
     }
 
@@ -595,7 +597,7 @@
 
     while (handle->redircount < 10) {
 
-        _DEBUG("Creating session");
+        _DEBUG("<%p> Creating session", handle);
         handle->session = ne_session_create(handle->purl->scheme, handle->purl->host, handle->purl->port);
         ne_add_server_auth(handle->session, NE_AUTH_BASIC, server_auth_callback, (void *)handle);
         ne_set_session_flag(handle->session, NE_SESSFLAG_ICYPROTO, 1);
@@ -609,11 +611,11 @@
         ne_redirect_register(handle->session);
 
         if (use_proxy) {
-            _DEBUG("Using proxy: %s:%d", proxy_host, proxy_port);
+            _DEBUG("<%p> Using proxy: %s:%d", handle, proxy_host, proxy_port);
             ne_session_proxy(handle->session, proxy_host, proxy_port);
         }
 
-        _DEBUG("Creating request");
+        _DEBUG("<%p> Creating request", handle);
         ret = open_request(handle, startbyte);
 
         if (0 == ret) {
@@ -628,7 +630,7 @@
      * If we get here, our redirect count exceeded
      */
 
-    _ERROR("Redirect count exceeded for URL");
+    _ERROR("<%p> Redirect count exceeded for URL %s", handle, handle->url);
 
     _LEAVE 1;
 }
@@ -648,22 +650,22 @@
     bsize = free_rb(&h->rb);
     to_read = MIN(bsize, NETBLKSIZ);
 
-    _DEBUG("%d bytes free in buffer, trying to read %d bytes max", bsize, to_read);
+    _DEBUG("<%p> %d bytes free in buffer, trying to read %d bytes max", h, bsize, to_read);
 
-    _DEBUG("Reading from the network....");
+    _DEBUG("<%p> Reading from the network....", h);
     if (0 >= (bsize = ne_read_response_block(h->request, buffer, to_read))) {
         if (0 == bsize) {
-            _DEBUG("End of file encountered");
+            _DEBUG("<%p> End of file encountered", h);
             _LEAVE 1;
         } else {
-            _ERROR("Error while reading from the network");
+            _ERROR("<%p> Error while reading from the network", h);
             _LEAVE -1;
         }
     }
-    _DEBUG("Read %d bytes from the network", bsize);
+    _DEBUG("<%p> Read %d bytes from the network", h, bsize);
 
     if (0 != write_rb(&(h->rb), buffer, bsize)) {
-        _ERROR("Error putting data into buffer");
+        _ERROR("<%p> Error putting data into buffer", h);
         _LEAVE -1;
     }
 
@@ -682,12 +684,12 @@
     _ENTER;
 
     bfree = free_rb(&h->rb);
-    _DEBUG("Filling buffer up to max %d bytes free, %d bytes free now", maxfree, bfree);
+    _DEBUG("<%p> Filling buffer up to max %d bytes free, %d bytes free now", h, maxfree, bfree);
 
     while (bfree > maxfree) {
         ret = fill_buffer(h);
         if (-1 == ret) {
-            _ERROR("Error while filling buffer");
+            _ERROR("<%p> Error while filling buffer", h);
             _LEAVE ret;
         } else if (1 == ret) {
             /*
@@ -723,7 +725,7 @@
         if (NETBLKSIZ < free_rb_locked(&h->rb)) {
             g_mutex_unlock(h->reader_status.mutex);
 
-            _DEBUG("Filling buffer...");
+            _DEBUG("<%p> Filling buffer...", h);
             ret = fill_buffer(h);
 
             g_mutex_lock(h->reader_status.mutex);
@@ -733,7 +735,7 @@
                  * Set the error flag and terminate the
                  * reader thread.
                  */
-                _ERROR("Error while reading from the network. Terminating reader thread");
+                _ERROR("<%p> Error while reading from the network. Terminating reader thread", h);
                 h->reader_status.status = NEON_READER_ERROR;
                 g_mutex_unlock(h->reader_status.mutex);
                 _LEAVE NULL;
@@ -742,7 +744,7 @@
                  * EOF encountered while reading from the
                  * network. Set the EOF status and exit.
                  */
-                _DEBUG("EOF encountered while reading from the network. Terminating reader thread");
+                _DEBUG("<%p> EOF encountered while reading from the network. Terminating reader thread", h);
                 h->reader_status.status = NEON_READER_EOF;
                 g_mutex_unlock(h->reader_status.mutex);
                 _LEAVE NULL;
@@ -751,19 +753,19 @@
             /*
              * So we actually got some data out of the stream.
              */
-            _DEBUG("Network read succeeded");
+            _DEBUG("<%p> Network read succeeded", h);
         } else {
             /*
              * Not enough free space in the buffer.
              * Sleep until the main thread wakes us up.
              */
-            _DEBUG("Reader thread going to sleep");
+            _DEBUG("<%p> Reader thread going to sleep", h);
             g_cond_wait(h->reader_status.cond, h->reader_status.mutex);
-            _DEBUG("Reader thread woke up");
+            _DEBUG("<%p> Reader thread woke up", h);
         }
     }
 
-    _DEBUG("Reader thread terminating gracefully");
+    _DEBUG("<%p> Reader thread terminating gracefully", h);
     h->reader_status.status = NEON_READER_TERM;
     g_mutex_unlock(h->reader_status.mutex);
 
@@ -794,15 +796,17 @@
         _LEAVE NULL;
     }
 
+    _DEBUG("Allocated new handle: %p", handle);
+
     if (NULL == (handle->url = strdup(path))) {
-        _ERROR("Could not copy URL string");
+        _ERROR("<%p> Could not copy URL string", handle);
         handle_free(handle);
         free(file);
         _LEAVE NULL;
     }
 
     if (0 != open_handle(handle, 0)) {
-        _ERROR("Could not open URL");
+        _ERROR("<%p> Could not open URL", handle);
         handle_free(handle);
         free(file);
         _LEAVE NULL;
@@ -828,12 +832,12 @@
         kill_reader(h);
     }
 
-    _DEBUG("Destroying request");
+    _DEBUG("<%p> Destroying request", h);
     if (NULL != h->request) {
         ne_request_destroy(h->request);
     }
 
-    _DEBUG("Destroying session");
+    _DEBUG("<%p> Destroying session", h);
     ne_session_destroy(h->session);
 
     handle_free(h);
@@ -857,12 +861,12 @@
     _ENTER;
 
     if (NULL == h->request) {
-        _ERROR("No request to read from, seek gone wrong?");
+        _ERROR("<%p> No request to read from, seek gone wrong?", h);
         _LEAVE 0;
     }
 
-    _DEBUG("Requesting %d elements of %d bytes size each (%d bytes total), to be stored at %p",
-            nmemb, size, (nmemb*size), ptr_);
+    _DEBUG("<%p> Requesting %d elements of %d bytes size each (%d bytes total), to be stored at %p",
+            h, nmemb, size, (nmemb*size), ptr_);
 
     /*
      * Look how much data is in the buffer
@@ -878,7 +882,7 @@
         g_mutex_lock(h->reader_status.mutex);
         if (NEON_READER_RUN == h->reader_status.status) {
             g_mutex_unlock(h->reader_status.mutex);
-            _ERROR("Buffer underrun, trying rebuffering");
+            _ERROR("<%p> Buffer underrun, trying rebuffering", h);
             kill_reader(h);
 
             /*
@@ -890,7 +894,7 @@
                 /*
                  * Reader thread did not terminate gracefully.
                  */
-                _ERROR("Reader thread did not terminate gracefully: %d", h->reader_status.status);
+                _ERROR("<%p> Reader thread did not terminate gracefully: %d", h, h->reader_status.status);
                 _LEAVE 0;
             }
         } else {
@@ -904,14 +908,14 @@
          * the network ourselves, and then fire up the reader thread
          * to keep the buffer filled up.
          */
-        _DEBUG("Doing initial buffer fill");
+        _DEBUG("<%p> Doing initial buffer fill", h);
         ret = fill_buffer_limit(h, NBUFSIZ/2);
 
         if (-1 == ret) {
-            _ERROR("Error while reading from the network");
+            _ERROR("<%p> Error while reading from the network", h);
             _LEAVE 0;
         } else if (1 == ret) {
-            _ERROR("EOF during initial read");
+            _ERROR("<%p> EOF during initial read", h);
             _LEAVE 0;
         }
 
@@ -924,7 +928,7 @@
         if (NULL == (h->reader = g_thread_create(reader_thread, h, TRUE, NULL))) {
             h->reader_status.reading = FALSE;
             g_mutex_unlock(h->reader_status.mutex);
-            _ERROR("Error creating reader thread!");
+            _ERROR("<%p> Error creating reader thread!", h);
             _LEAVE 0;
         }
         h->reader_status.status = NEON_READER_RUN;
@@ -935,7 +939,7 @@
          * shape.
          */
         g_mutex_lock(h->reader_status.mutex);
-        _DEBUG("Reader thread status: %d", h->reader_status.status);
+        _DEBUG("<%p> Reader thread status: %d", h, h->reader_status.status);
         switch (h->reader_status.status) {
             case NEON_READER_INIT:
             case NEON_READER_RUN:
@@ -949,7 +953,7 @@
                  * If not, terminate the reader thread and return 0.
                  */
                 if (0 == used_rb_locked(&h->rb)) {
-                    _DEBUG("Reached end of stream");
+                    _DEBUG("<%p> Reached end of stream", h);
                     g_mutex_unlock(h->reader_status.mutex);
                     kill_reader(h);
                     h->eof = TRUE;
@@ -968,7 +972,7 @@
                  * likely on our own request.
                  * We should not get here.
                  */
-                _ERROR("Reader thread terminated and fread() called. How did we get here?");
+                _ERROR("<%p> Reader thread terminated and fread() called. How did we get here?", h);
                 g_mutex_unlock(h->reader_status.mutex);
                 kill_reader(h);
                 _LEAVE 0;
@@ -983,12 +987,12 @@
         /*
          * The buffer is still empty, we can deliver no data!
          */
-        _ERROR("Buffer still underrun, fatal.");
+        _ERROR("<%p> Buffer still underrun, fatal.", h);
         _LEAVE 0;
     }
 
     if (0 != h->icy_metaint) {
-        _DEBUG("%ld bytes left before next ICY metadata announcement", h->icy_metaleft);
+        _DEBUG("<%p> %ld bytes left before next ICY metadata announcement", h, h->icy_metaleft);
         if (0 == h->icy_metaleft) {
             /*
              * The next data in the buffer is a ICY metadata announcement.
@@ -1001,14 +1005,14 @@
              * a) Read the complete ICY metadata block
              * b) deliver at least one byte to the reader
              */
-            _DEBUG("Expecting %d bytes of ICY metadata", (icy_metalen*16));
+            _DEBUG("<%p> Expecting %d bytes of ICY metadata", h, (icy_metalen*16));
 
             if ((free_rb(&h->rb)-(icy_metalen*16)) < size) {
                 /* There is not enough data. We do not have much choice at this point,
                  * so we'll deliver the metadata as normal data to the reader and
                  * hope for the best.
                  */
-                _ERROR("Buffer underrun when reading metadata. Expect audio degradation");
+                _ERROR("<%p> Buffer underrun when reading metadata. Expect audio degradation", h);
                 h->icy_metaleft = h->icy_metaint + (icy_metalen*16);
             } else {
                 /*
@@ -1030,13 +1034,13 @@
     }
 
     relem = MIN(belem, nmemb);
-    _DEBUG("%d elements of returnable data in the buffer", belem);
+    _DEBUG("<%p> %d elements of returnable data in the buffer", h, belem);
     read_rb(&h->rb, ptr_, relem*size);
 
     /*
      * Signal the network thread to continue reading
      */
-    _DEBUG("Waking up reader thread");
+    _DEBUG("<%p> Waking up reader thread", h);
     g_mutex_lock(h->reader_status.mutex);
     g_cond_signal(h->reader_status.cond);
     g_mutex_unlock(h->reader_status.mutex);
@@ -1044,7 +1048,7 @@
     h->pos += (relem*size);
     h->icy_metaleft -= (relem*size);
 
-    _DEBUG("Returning %d elements", relem);
+    _DEBUG("<%p> Returning %d elements", h, relem);
 
     _LEAVE relem;
 }
@@ -1058,7 +1062,7 @@
 
     _ENTER;
 
-    _ERROR("NOT IMPLEMENTED");
+    _ERROR("<%p> NOT IMPLEMENTED", file->handle);
 
     _LEAVE 0;
 }
@@ -1074,7 +1078,7 @@
     _ENTER;
 
     if (1 != neon_aud_vfs_fread_impl(&c, 1, 1, file)) {
-        _ERROR("Could not getc()!");
+        _ERROR("<%p> Could not getc()!", file->handle);
         _LEAVE -1;
     }
 
@@ -1089,7 +1093,7 @@
 
     _ENTER;
 
-    _ERROR("NOT IMPLEMENTED");
+    _ERROR("<%p> NOT IMPLEMENTED", file->handle);
 
     _LEAVE 0;
 }
@@ -1117,7 +1121,7 @@
 
     _ENTER;
 
-    _DEBUG("Current file position: %ld", h->pos);
+    _DEBUG("<%p> Current file position: %ld", h, h->pos);
 
     _LEAVE h->pos;
 }
@@ -1143,7 +1147,7 @@
 
     _ENTER;
 
-    _ERROR("NOT IMPLEMENTED");
+    _ERROR("<%p> NOT IMPLEMENTED", file->handle);
 
     _LEAVE 0;
 }
@@ -1160,14 +1164,14 @@
 
     _ENTER;
 
-    _DEBUG("Seek requested: offset %ld, whence %d", offset, whence);
+    _DEBUG("<%p> Seek requested: offset %ld, whence %d", h, offset, whence);
     /*
      * Two things must be satisfied for us to be able to seek:
      * - the server must advertise a content-length
      * - the server must advertise accept-ranges: bytes
      */
     if ((-1 == h->content_length) || !h->can_ranges) {
-        _DEBUG("Can not seek due to server restrictions");
+        _DEBUG("<%p> Can not seek due to server restrictions", h);
         _LEAVE -1;
     }
 
@@ -1184,18 +1188,18 @@
             newpos = content_length + offset;
             break;
         default:
-            _ERROR("Invalid whence specified");
+            _ERROR("<%p> Invalid whence specified", h);
             _LEAVE -1;
     }
 
-    _DEBUG("Position to seek to: %ld, current: %ld", newpos, h->pos);
+    _DEBUG("<%p> Position to seek to: %ld, current: %ld", h, newpos, h->pos);
     if (0 > newpos) {
-        _ERROR("Can not seek before start of stream");
+        _ERROR("<%p> Can not seek before start of stream", h);
 	_LEAVE -1;
     }
 
     if (newpos > content_length) {
-        _ERROR("Can not seek beyond end of stream");
+        _ERROR("<%p> Can not seek beyond end of stream", h);
         _LEAVE -1;
     }
 
@@ -1228,7 +1232,7 @@
          * to NULL, so that fread() will error out on the next
          * read request
          */
-        _ERROR("Error while creating new request!");
+        _ERROR("<%p> Error while creating new request!", h);
         h->request = NULL;
         _LEAVE -1;
     }
@@ -1251,7 +1255,7 @@
 
     _ENTER;
 
-    _DEBUG("Field name: %s", field);
+    _DEBUG("<%p> Field name: %s", h, field);
 
     if (0 == g_ascii_strncasecmp(field, "track-name", 10)) {
         _LEAVE g_strdup(h->icy_metadata.stream_title);
@@ -1279,7 +1283,7 @@
     _ENTER;
 
     if (-1 == h->content_length) {
-        _DEBUG("Unknown content length");
+        _DEBUG("<%p> Unknown content length", h);
         _LEAVE -1;
     }