Add volumeids to log messages

volumes/processing/service/SliceGenerator.py

@@ -1,6 +1,7 @@
 import re
 import time
 import math
+import sys
 
 from threading import Thread
 from multiprocessing import Process, cpu_count, Queue
@@ -83,19 +84,19 @@ def sliceGeneratorPlain(data, volumeId):
     frames = []
     try:
         if volume.imageSequence is True:
-            logger.debug('reading imagesequence')
+            logger.debug('volId: %s, reading imagesequence' % (volumeId))
             frames = tiffPreparer.prepareImageSequence(volume.path)
         elif re.search(r'.tif(f|)$', volume.path):
-            logger.debug('reading tiff file')
+            logger.debug('volId: %s, reading tiff file' % (volumeId))
             frames = tiffPreparer.processTiffFile(volume.path)
         elif volume.rawData:
-            logger.debug('reading raw data')
+            logger.debug('volId: %s, reading raw data' % (volumeId))
             frames = binaryPreparer.processBinary(volume.path, (volume.width, volume.height), littleEndian = volume.littleEndian)
         else:
             raise ValueError('sorry, file currently not supported, is it a raw file?')
 
     except Exception as e:
-        logger.error(str(e))
+        logger.error('volId: %s, exception: %s)' % (volumeId, str(e)))
         volume.generateSlicesStatus = str(e)
         volume.save()
         return
@@ -103,14 +104,14 @@ def sliceGeneratorPlain(data, volumeId):
     try:
         sliceFrom, sliceTo = __defineSliceRange(frames, sliceFrom, sliceTo)
     except Exception:
-        logger.error('please provide integers or "" for "sliceFrom" and "sliceTo"')
+        logger.error('volId: %s, please provide integers or "" for "sliceFrom" and "sliceTo"' % (volumeId))
         Volume.objects(id=volume.id).update_one(set__generateSlicesStatus = 'generation failed, please read the logs')
         return
 
     if len(frames.shape) is not 4:
         raise ValueError('read input file shall have dim of 4, please check the used fileparser')
 
-    logger.debug('cropping images to be square')
+    logger.debug('volId: %s, cropping images to be square' % volumeId)
     oldshape = frames.shape
     pixelOffset, newSize = sliceMapCreator.calculateXYDimensions(frames[0])
     croppedFrames = np.empty((frames.shape[0], frames.shape[1], newSize[1], newSize[0]), dtype=frames.dtype)
@@ -118,92 +119,91 @@ def sliceGeneratorPlain(data, volumeId):
         croppedFrames[frameNumber] = sliceMapCreator.cropFrame(frames[frameNumber], pixelOffset, newSize)
 
     del frames
-    logger.debug('memory freed, frames deleted, keeping squared croppedFrames')
+    logger.debug('volId: %s, memory freed, frames deleted, keeping squared croppedFrames' % volumeId)
 
     if croppedFrames.dtype == np.float32 or croppedFrames.dtype == np.float16:
-        logger.debug('float frames detected, normalize them')
+        logger.debug('volId: %s, float frames detected, normalize them' % volumeId)
         collectionMin = croppedFrames.min()
         collectionMax = croppedFrames.max()
-        logger.debug('imagesmin: %d, imagesmax: %d' %(collectionMin, collectionMax))
+        logger.debug('volId: %s, imagesmin: %d, imagesmax: %d' %(volumeId, collectionMin, collectionMax))
         croppedFrames = (croppedFrames - collectionMin) / (collectionMax - collectionMin)
 
-        logger.debug('after normalization imagesmin: %d, imagesmax: %d' %(croppedFrames.min(), croppedFrames.max()))
+        logger.debug('volId: %s, after normalization imagesmin: %d, imagesmax: %d' %(volumeId, croppedFrames.min(), croppedFrames.max()))
     else:
-        logger.debug('frames do NOT have to be normalized, dtype is %s' % str(croppedFrames.dtype))
+        logger.debug('volId: %s, frames do NOT have to be normalized, dtype is %s' % (volumeId, str(croppedFrames.dtype)))
 
     if croppedFrames.dtype != np.int16 and croppedFrames.dtype != np.uint8:
-        logger.debug('frames are not int16 and not uint8, convert them to int')
+        logger.debug('volId: %s, frames are not int16 and not uint8, convert them to int' % volumeId)
         croppedFrames = img_as_int(croppedFrames)
     else:
-        logger.debug('frames are not converted because of dtype %s' % str(croppedFrames.dtype))
+        logger.debug('volId: %s, frames are not converted because of dtype %s' % (volumeId, str(croppedFrames.dtype)))
 
     rawFrame = None
     # the file on disk has changed, we have to save it in the database
     if fileChanged or len(volume.rawFrames) == 0:
         if settings.REDUCE_HARDDISK_ACCESS_FOR_DEV is False:
-            logger.debug('deleting rawframes from volume')
+            logger.debug('volId: %s, deleting rawframes from volume' % volumeId)
             volume.remove_frames()
         else:
-            logger.debug('not deleting rawframes from volume --> reducing harddisk access')
+            logger.debug('volId: %s, not deleting rawframes from volume --> reducing harddisk access' % volumeId)
 
-        logger.debug('setting rawframes')
+        logger.debug('volId: %s, setting rawframes' % volumeId)
 
         for frameNumber in range(0, len(croppedFrames)):
+            logger.debug('volId: %s, rawFrame: %d, sizeInMemory: %d' % (volumeId, frameNumber, sys.getsizeof(croppedFrames[frameNumber])))
             rawFrame = volume.add_frame(croppedFrames[frameNumber], frameNumber)
     else:
         rawFrame = volume.rawFrames[0]
 
-    logger.debug('rawframes have been appended to volume')
+    logger.debug('volId: %s, rawframes have been appended to volume' % volumeId)
 
     try:
-        logger.debug('convert images to ubyte for generating preview textures')
+        logger.debug('volId: %s, convert images to ubyte for generating preview textures' % volumeId)
         framesUByte = MultiProcessUByte.multiprocess_img_as_ubyte(croppedFrames)
         del croppedFrames
-        logger.debug('memory freed, croppedFrames deleted, keeping ubyte frames')
+        logger.debug('volId: %s, memory freed, croppedFrames deleted, keeping ubyte frames' % volumeId)
     except Exception as e:
-        logger.error(str(e))
+        logger.error('volId: %s, exception: %s' % (volumeId, str(e)))
         Volume.objects(id=volume.id).update_one(set__generateSlicesStatus = str(e))
         return
 
-    logger.debug('converting ended')
+    logger.debug('volId: %s, converting ended' % volumeId)
 
     originalSize = rawFrame.originalSize
 
-    volumeId = volume.id
-
     # free more memory
-    logger.debug('del volume now, free memory')
+    logger.debug('volId: %s, del volume object now from RAM, free memory' % volumeId)
     del volume
 
     volume = Volume.objects(id=volumeId)[0]
     try:
-        logger.debug('processing the image now')
+        logger.debug('volId: %s, processing the image now' % volumeId)
         sprites = sliceMapCreator.processFrames(framesUByte, 0, len(framesUByte - 1), sliceFrom, sliceTo, imgFormat, size)
 
         infoObject = sliceMapCreator.generateInfo(sprites, 0, len(framesUByte) - 1, sliceFrom, sliceTo)
     except Exception as e:
-        logger.error(str(e))
+        logger.error('volId: %s, exception: %s' % (volumeId, str(e)))
         Volume.objects(id=volume.id).update_one(set__generateSlicesStatus = str(e))
         return
 
     try:
         volume.clear_textures()
     except Exception as e:
-        logger.error(str(e))
+        logger.error('volId: %s, exception: %s' % (volumeId, str(e)))
         Volume.objects(id=volume.id).update_one(set__generateSlicesStatus = str(e))
         return
 
     try:
-        logger.debug('save sprites in volume')
+        logger.debug('volId: %s, save sprites in volume' % volumeId)
         for key in sprites:
             volume.add_slice_maps(int(key), sprites[key], originalSize, infoObject)
     except Exception as e:
-        logger.error(str(e))
+        logger.error('volId: %s, exception: %s' % (volumeId, str(e)))
         Volume.objects(id=volume.id).update_one(set__generateSlicesStatus = str(e))
         return
 
     Volume.objects(id=volume.id).update_one(set__generateSlicesStatus = 'generation successful')
-    logger.debug('generation successful')
+    logger.debug('volId: %s, generation successful' % volumeId)
 
 
 '''