Merge branch 'PHRAS-3474-mapping-client-annotation' of https://github.com/alchemy-fr/Phraseanet into PHRAS-3474-mapping-client-annotation

lib/Alchemy/Phrasea/Border/Checker/Sha256.php

@@ -34,6 +34,10 @@ class Sha256 extends AbstractChecker
      */
     public function check(EntityManager $em, File $file)
     {
+        file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("\n%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("into checker sha256")
+        ), FILE_APPEND | LOCK_EX);
+
         $excludedCollIds = [];
         if (!empty($this->compareIgnoreCollections)) {
             foreach ($this->compareIgnoreCollections as $collection) {
@@ -46,6 +50,10 @@ class Sha256 extends AbstractChecker
 
         $boolean = empty($file->getCollection()->get_databox()->getRecordRepository()->findBySha256WithExcludedCollIds($file->getSha256(), $excludedCollIds));
 
+        file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("return from checker sha256")
+        ), FILE_APPEND | LOCK_EX);
+
         return new Response($boolean, $this);
     }
 

lib/Alchemy/Phrasea/Border/Checker/UUID.php

@@ -33,6 +33,10 @@ class UUID extends AbstractChecker
      */
     public function check(EntityManager $em, File $file)
     {
+        file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("\n%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("into checker uuid")
+        ), FILE_APPEND | LOCK_EX);
+
         $excludedCollIds = [];
         if (!empty($this->compareIgnoreCollections)) {
             foreach ($this->compareIgnoreCollections as $collection) {
@@ -43,7 +47,22 @@ class UUID extends AbstractChecker
             }
         }
 
-        $boolean = empty($file->getCollection()->get_databox()->getRecordRepository()->findByUuidWithExcludedCollIds($file->getUUID(), $excludedCollIds));
+        $uuid = $file->getUUID(false, false);
+        file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("found uuid=%s", $uuid ?: 'null')
+        ), FILE_APPEND | LOCK_EX);
+
+        if($uuid === null) {
+            // no uuid in file so no need to search for a match
+            $boolean = true;
+        }
+        else {
+            $boolean = empty($file->getCollection()->get_databox()->getRecordRepository()->findByUuidWithExcludedCollIds($uuid, $excludedCollIds));
+        }
+
+        file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("return from checker uuid")
+        ), FILE_APPEND | LOCK_EX);
 
         return new Response($boolean, $this);
     }

lib/Alchemy/Phrasea/Border/File.php

@@ -63,6 +63,10 @@ class File
      */
     public function __construct(Application $app, MediaInterface $media, \collection $collection, $originalName = null)
     {
+        file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("into construct")
+        ), FILE_APPEND | LOCK_EX);
+
         $this->app = $app;
         $this->media = $media;
         $this->collection = $collection;
@@ -83,17 +87,21 @@ class File
     /**
      * Checks for UUID in metadatas
      *
-     * @todo Check if a file exists with the same checksum
-     * @todo Check if an UUID is contained in the attributes, replace It if
-     *              necessary
-     *
      * @param  boolean $generate if true, if no uuid found, a valid one is generated
      * @param  boolean $write    if true, writes uuid in all available metadatas
-     * @return File
+     * @return string
      */
     public function getUUID($generate = false, $write = false)
     {
+        file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("into getuuid for \"%s\" with generate=%s, write=%s ; this->uuid=%s", $this->getFile()->getRealPath(), $generate?'true':'false', $write?'true':'false', $this->uuid ?:'null')
+        ), FILE_APPEND | LOCK_EX);
+
         if ($this->uuid && !$write) {
+            file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                sprintf("return known uuid %s", $this->uuid)
+            ), FILE_APPEND | LOCK_EX);
+
             return $this->uuid;
         }
 
@@ -107,6 +115,10 @@ class File
         ];
 
         if (!$this->uuid) {
+            file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                sprintf("getMetadatas to get uuid")
+            ), FILE_APPEND | LOCK_EX);
+
             $metadatas = $this->media->getMetadatas();
 
             $uuid = null;
@@ -119,6 +131,11 @@ class File
                     }
                     if (Uuid::isValid($candidate)) {
                         $uuid = $candidate;
+
+                        file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                            sprintf("found uuid from %s ; %s", $meta, $uuid)
+                        ), FILE_APPEND | LOCK_EX);
+
                         break;
                     }
                 }
@@ -126,12 +143,19 @@ class File
 
             if (!$uuid && $generate) {
                 $uuid = Uuid::uuid4();
+                file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                    sprintf("generated uuid %s", $uuid)
+                ), FILE_APPEND | LOCK_EX);
             }
 
             $this->uuid = $uuid;
         }
 
         if ($write) {
+            file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                sprintf("writing uuid %s", $this->uuid)
+            ), FILE_APPEND | LOCK_EX);
+
             $value = new MonoValue($this->uuid);
             $metadatas = new ExiftoolMetadataBag();
 
@@ -142,12 +166,31 @@ class File
             try {
                 $writer = $this->app['exiftool.writer'];
                 $writer->reset();
+
+                file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                    sprintf("exiftool will write to %s", $this->getFile()->getRealPath())
+                ), FILE_APPEND | LOCK_EX);
+
                 $writer->write($this->getFile()->getRealPath(), $metadatas);
+
+                file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                    sprintf("exiftool has writen ok to %s", $this->getFile()->getRealPath())
+                ), FILE_APPEND | LOCK_EX);
+
             } catch (PHPExiftoolException $e) {
+
+                file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                    sprintf("exiftool failed to write to %s because (%s)", $this->getFile()->getRealPath(), $e->getMessage())
+                ), FILE_APPEND | LOCK_EX);
+
                 // PHPExiftool throws exception on some files not supported
             }
         }
 
+        file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("return uuid %s", $this->uuid ?: 'null')
+        ), FILE_APPEND | LOCK_EX);
+
         return $this->uuid;
     }
 
@@ -186,9 +229,30 @@ class File
      */
     public function getSha256()
     {
+        file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("into getSha256() for \"%s\" ; this->sha256=%s", $this->getFile()->getRealPath(), $this->sha256 ?: 'null')
+        ), FILE_APPEND | LOCK_EX);
+
         if (!$this->sha256) {
+            file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                sprintf("sha256 unknown, calling mediavorus::getHash('sha256')")
+            ), FILE_APPEND | LOCK_EX);
+
             $this->sha256 = $this->media->getHash('sha256');
+
+            file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                sprintf("mediavorus::getHash('sha256') returned \"%s\"", $this->sha256)
+            ), FILE_APPEND | LOCK_EX);
         }
+        else {
+            file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                sprintf("sha256 known (\"%s\")", $this->sha256)
+            ), FILE_APPEND | LOCK_EX);
+        }
+
+        file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("return sha256 %s", $this->sha256 ?: 'null')
+        ), FILE_APPEND | LOCK_EX);
 
         return $this->sha256;
     }

lib/Alchemy/Phrasea/Border/Manager.php

@@ -12,20 +12,21 @@
 namespace Alchemy\Phrasea\Border;
 
 use Alchemy\Phrasea\Application;
-use Alchemy\Phrasea\Border\Checker\CheckerInterface;
 use Alchemy\Phrasea\Border\Attribute\AttributeInterface;
-use Alchemy\Phrasea\Core\Event\Record\RecordEvents;
-use Alchemy\Phrasea\Core\Event\Record\SubdefinitionCreateEvent;
-use Alchemy\Phrasea\Exception\RuntimeException;
-use Alchemy\Phrasea\Metadata\Tag\TfArchivedate;
-use Alchemy\Phrasea\Metadata\Tag\TfQuarantine;
-use Alchemy\Phrasea\Metadata\Tag\TfBasename;
-use Alchemy\Phrasea\Metadata\Tag\TfFilename;
-use Alchemy\Phrasea\Metadata\Tag\TfRecordid;
 use Alchemy\Phrasea\Border\Attribute\Metadata as MetadataAttr;
 use Alchemy\Phrasea\Border\Attribute\MetaField as MetafieldAttr;
 use Alchemy\Phrasea\Border\Attribute\Status as StatusAttr;
 use Alchemy\Phrasea\Border\Attribute\Story as StoryAttr;
+use Alchemy\Phrasea\Border\Checker\CheckerInterface;
+use Alchemy\Phrasea\Core\Event\Record\RecordEvents;
+use Alchemy\Phrasea\Core\Event\Record\SubdefinitionCreateEvent;
+use Alchemy\Phrasea\Exception\RuntimeException;
+use Alchemy\Phrasea\Metadata\PhraseanetMetadataSetter;
+use Alchemy\Phrasea\Metadata\Tag\TfArchivedate;
+use Alchemy\Phrasea\Metadata\Tag\TfBasename;
+use Alchemy\Phrasea\Metadata\Tag\TfFilename;
+use Alchemy\Phrasea\Metadata\Tag\TfQuarantine;
+use Alchemy\Phrasea\Metadata\Tag\TfRecordid;
 use Alchemy\Phrasea\Model\Entities\LazaretAttribute;
 use Alchemy\Phrasea\Model\Entities\LazaretCheck;
 use Alchemy\Phrasea\Model\Entities\LazaretFile;
@@ -105,27 +106,61 @@ class Manager
      */
     public function process(LazaretSession $session, File $file, $callable = null, $forceBehavior = null, $nosubdef = false)
     {
+        file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("into process")
+        ), FILE_APPEND | LOCK_EX);
+
         $visa = $this->getVisa($file);
 
-        // Generate UUID
+        // READ the uuid (possibly generates one) but DO NOT write (because we need the stripped file for sha compare ?)
+        file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("get uuid (generate, no write) from \"%s\"", $file->getFile()->getRealPath())
+        ), FILE_APPEND | LOCK_EX);
+
         $file->getUUID(true, false);
 
         if (($visa->isValid() || $forceBehavior === self::FORCE_RECORD) && $forceBehavior !== self::FORCE_LAZARET) {
 
             $this->addMediaAttributes($file);
 
+            // Write UUID
+            file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                sprintf("get uuid (no generate, write) from \"%s\"", $file->getFile()->getRealPath())
+            ), FILE_APPEND | LOCK_EX);
+
+            $file->getUUID(false, true);
+
+            file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                sprintf("creating record")
+            ), FILE_APPEND | LOCK_EX);
+
             $element = $this->createRecord($file, $nosubdef);
 
             $code = self::RECORD_CREATED;
         } else {
 
+            // Write UUID
+            file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                sprintf("get uuid (no generate, write) from \"%s\"", $file->getFile()->getRealPath())
+            ), FILE_APPEND | LOCK_EX);
+
+            $file->getUUID(false, true);
+
+            file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                sprintf("creating lazaret")
+            ), FILE_APPEND | LOCK_EX);
+
             $element = $this->createLazaret($file, $visa, $session, $forceBehavior === self::FORCE_LAZARET);
 
             $code = self::LAZARET_CREATED;
         }
 
-        // Write UUID
-        $file->getUUID(false, true);
+//        // Write UUID
+//        file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+//            sprintf("get uuid (no generate, write) from \"%s\"", $file->getFile()->getRealPath())
+//        ), FILE_APPEND | LOCK_EX);
+//
+//        $file->getUUID(false, true);
 
         if (is_callable($callable)) {
             $callable($element, $visa, $code);
@@ -267,7 +302,17 @@ class Manager
      */
     protected function createRecord(File $file, $nosubdef=false)
     {
+        file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("into createRecord")
+        ), FILE_APPEND | LOCK_EX);
+
         $element = \record_adapter::createFromFile($file, $this->app);
+
+        file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("created %s.%s", $element->getDataboxId(), $element->getRecordId())
+        ), FILE_APPEND | LOCK_EX);
+
+
         $date = new \DateTime();
 
         $file->addAttribute(
@@ -332,7 +377,13 @@ class Manager
             }
         }
 
-        $this->app['phraseanet.metadata-setter']->replaceMetadata($newMetadata, $element);
+        file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("calling replaceMetadata")
+        ), FILE_APPEND | LOCK_EX);
+
+        /** @var PhraseanetMetadataSetter $phraseanetMetadataSetter */
+        $phraseanetMetadataSetter = $this->app['phraseanet.metadata-setter'];
+        $phraseanetMetadataSetter->replaceMetadata($newMetadata, $element);
 
         if(!$nosubdef) {
             $this->app['dispatcher']->dispatch(RecordEvents::SUBDEFINITION_CREATE, new SubdefinitionCreateEvent($element, true));
@@ -353,6 +404,10 @@ class Manager
      */
     protected function createLazaret(File $file, Visa $visa, LazaretSession $session, $forced)
     {
+        file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("into createLazaret")
+        ), FILE_APPEND | LOCK_EX);
+
         $date = new \DateTime();
         $file->addAttribute(
             new MetadataAttr(
@@ -405,6 +460,10 @@ class Manager
 
         $this->app['orm.em']->flush();
 
+        file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("return from createLazaret")
+        ), FILE_APPEND | LOCK_EX);
+
         return $lazaretFile;
     }
 

lib/Alchemy/Phrasea/Controller/Prod/UploadController.php

@@ -117,6 +117,10 @@ class UploadController extends Controller
      */
     public function upload(Request $request)
     {
+        file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("into upload controller")
+        ), FILE_APPEND | LOCK_EX);
+
         $data = [
             'success' => false,
             'code'    => null,
@@ -194,12 +198,21 @@ class UploadController extends Controller
                 $renamedFilename = $file->getRealPath() . '.' . pathinfo($file->getClientOriginalName(), PATHINFO_EXTENSION);
             }
 
+            file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                sprintf("rename \"%s\" to \"%s\"", $uploadedFilename, $renamedFilename)
+            ), FILE_APPEND | LOCK_EX);
+
             $this->getFilesystem()->rename($uploadedFilename, $renamedFilename);
 
             $originalName = $file->getClientOriginalName();
         }
 
         try {
+            file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                sprintf("calling getMediaFromUri(\"%s\")", $renamedFilename)
+            ), FILE_APPEND | LOCK_EX);
+
+
             $media = $this->app->getMediaFromUri($renamedFilename);
             $collection = \collection::getByBaseId($this->app, $base_id);
 
@@ -228,7 +241,15 @@ class UploadController extends Controller
             $elementCreated = null;
 
             $callback = function ($element, Visa $visa) use (&$reasons, &$elementCreated) {
+                file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                    sprintf("into callback")
+                ), FILE_APPEND | LOCK_EX);
+
                 foreach ($visa->getResponses() as $response) {
+                    file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                        sprintf("visa returned %s", $response->isOk() ? 'ok' : 'not ok')
+                    ), FILE_APPEND | LOCK_EX);
+
                     if (!$response->isOk()) {
                         $reasons[] = $response->getMessage($this->app['translator']);
                     }
@@ -237,10 +258,23 @@ class UploadController extends Controller
                 $elementCreated = $element;
             };
 
+            file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                sprintf("process")
+            ), FILE_APPEND | LOCK_EX);
+
             $code = $this->getBorderManager()->process( $lazaretSession, $packageFile, $callback, $forceBehavior);
 
+            file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                sprintf("processed, returned elementCreated class \"%s\"", get_class($elementCreated))
+            ), FILE_APPEND | LOCK_EX);
+
             if($renamedFilename !== $uploadedFilename) {
                 $this->getFilesystem()->rename($renamedFilename, $uploadedFilename);
+
+                file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                    sprintf("renamed \"%s\" back to \"%s\"", $renamedFilename, $uploadedFilename)
+                ), FILE_APPEND | LOCK_EX);
+
             }
 
             if (!!$forceBehavior) {
@@ -248,10 +282,19 @@ class UploadController extends Controller
             }
 
             if ($elementCreated instanceof \record_adapter) {
+
+                file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                    sprintf("record %s created", $elementCreated->getRecordId())
+                ), FILE_APPEND | LOCK_EX);
+
                 $id = $elementCreated->getId();
                 $element = 'record';
                 $message = $this->app->trans('The record was successfully created');
 
+                file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                    sprintf("dispatch event RECORD_UPLOAD")
+                ), FILE_APPEND | LOCK_EX);
+
                 $this->dispatch(PhraseaEvents::RECORD_UPLOAD, new RecordEdit($elementCreated));
 
                 // try to create thumbnail from data URI
@@ -261,8 +304,17 @@ class UploadController extends Controller
 
                         $fileName = $this->getTemporaryFilesystem()->createTemporaryFile('base_64_thumb', null, "png");
                         file_put_contents($fileName, $dataUri->getData());
+
+                        file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                            sprintf("calling getMediaFromUri(\"%s\")", $fileName)
+                        ), FILE_APPEND | LOCK_EX);
+
                         $media = $this->app->getMediaFromUri($fileName);
 
+                        file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                            sprintf("getMediaFromUri(...) done")
+                        ), FILE_APPEND | LOCK_EX);
+
                         $this->getSubDefinitionSubstituer()->substituteSubdef($elementCreated, 'thumbnail', $media);
                         $this->getDataboxLogger($elementCreated->getDatabox())
                             ->log($elementCreated, \Session_Logger::EVENT_SUBSTITUTE, 'thumbnail', '');
@@ -275,6 +327,10 @@ class UploadController extends Controller
                 }
             } else {
                 /** @var LazaretFile $elementCreated */
+                file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                    sprintf("dispatch event LAZARET_CREATE")
+                ), FILE_APPEND | LOCK_EX);
+
                 $this->dispatch(PhraseaEvents::LAZARET_CREATE, new LazaretEvent($elementCreated));
 
                 $id = $elementCreated->getId();
@@ -294,6 +350,10 @@ class UploadController extends Controller
             $data['message'] = $this->app->trans('Unable to add file to Phraseanet');
         }
 
+        file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("returns")
+        ), FILE_APPEND | LOCK_EX);
+
         $response = $this->app->json($data);
         // IE 7 and 8 does not correctly handle json response in file API
         // lets send them an html content-type header

lib/Alchemy/Phrasea/Metadata/PhraseanetMetadataSetter.php

@@ -42,6 +42,10 @@ class PhraseanetMetadataSetter
      */
     public function replaceMetadata($metadataCollection, \record_adapter $record)
     {
+        file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("replaceMetadata for %s.%s", $record->getDataboxId(), $record->getRecordId())
+        ), FILE_APPEND | LOCK_EX);
+
         $metaStructure = $this->repository->find($record->getDataboxId())->get_meta_structure()->get_elements();
 
         $metadataPerField = $this->extractMetadataPerField($metaStructure, $metadataCollection);
@@ -88,12 +92,27 @@ class PhraseanetMetadataSetter
         }
 
         if (! empty($metadataInRecordFormat)) {
+            file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                sprintf("calling set_metadatas for %s.%s", $record->getDataboxId(), $record->getRecordId())
+            ), FILE_APPEND | LOCK_EX);
+
             $record->set_metadatas($metadataInRecordFormat, true);
 
             // order to write meta in file
+            file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                sprintf("dispatch WorkerEvents::RECORDS_WRITE_META for %s.%s", $record->getDataboxId(), $record->getRecordId())
+            ), FILE_APPEND | LOCK_EX);
+
             $this->dispatcher->dispatch(WorkerEvents::RECORDS_WRITE_META,
                 new RecordsWriteMetaEvent([$record->getRecordId()], $record->getDataboxId()));
         }
+        else {
+
+            file_put_contents(dirname(__FILE__).'/../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                sprintf("no metadatas to set for %s.%s", $record->getDataboxId(), $record->getRecordId())
+            ), FILE_APPEND | LOCK_EX);
+
+        }
     }
 
     /**

lib/Alchemy/Phrasea/Model/Manipulator/LazaretManipulator.php

@@ -129,6 +129,10 @@ class LazaretManipulator
     {
         $ret = ['success' => false, 'message' => '', 'result'  => []];
 
+        file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("into lazaret/add")
+        ), FILE_APPEND | LOCK_EX);
+
         /* @var LazaretFile $lazaretFile */
         $lazaretFile = $this->repository->find($file_id);
 
@@ -143,12 +147,21 @@ class LazaretManipulator
         $lazaretThumbFileName = $path .'/'.$lazaretFile->getThumbFilename();
 
         try {
+            file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                sprintf("ok to add from lazaret")
+            ), FILE_APPEND | LOCK_EX);
+
             $borderFile = Border\File::buildFromPathfile(
                 $lazaretFileName,
                 $lazaretFile->getCollection($this->app),
                 $this->app,
                 $lazaretFile->getOriginalName()
             );
+
+            file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                sprintf("got borderFile \"%s\"", $borderFile->getFile()->getRealPath())
+            ), FILE_APPEND | LOCK_EX);
+
         }
         catch(\Exception $e) {
             // the file is not in tmp anymore ?
@@ -159,8 +172,17 @@ class LazaretManipulator
             return $ret;
         }
 
+        file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("added from lazaret")
+        ), FILE_APPEND | LOCK_EX);
+
         try {
             //Post record creation
+
+            file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                sprintf("force record creation")
+            ), FILE_APPEND | LOCK_EX);
+
             /** @var \record_adapter $record */
             $record = null;
             $callBack = function ($element) use (&$record) {
@@ -175,9 +197,17 @@ class LazaretManipulator
                 Border\Manager::FORCE_RECORD
             );
 
+            file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                sprintf("got record %s.%s", $record->getDataboxId(), $record->getRecordId())
+            ), FILE_APPEND | LOCK_EX);
+
             if ($keepAttributes) {
                 //add attribute
 
+                file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                    sprintf("adding attributes")
+                ), FILE_APPEND | LOCK_EX);
+
                 $metaFields = new Border\MetaFieldsBag();
                 $metadataBag = new Border\MetadataBag();
 
@@ -217,13 +247,29 @@ class LazaretManipulator
                     }
                 }
 
+                /* todo: better to to do only one set_metadatas ? */
                 $data = $metadataBag->toMetadataArray($record->getDatabox()->get_meta_structure());
+
+                file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                    sprintf("adding attributes \"databag\" %s.%s", $record->getDataboxId(), $record->getRecordId())
+                ), FILE_APPEND | LOCK_EX);
+
                 $record->set_metadatas($data);
 
                 $fields = $metaFields->toMetadataArray($record->getDatabox()->get_meta_structure());
+
+                file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                    sprintf("adding attributes \"fields\" %s.%s", $record->getDataboxId(), $record->getRecordId())
+                ), FILE_APPEND | LOCK_EX);
+
                 $record->set_metadatas($fields);
 
+
                 // order to write meta in file
+                file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                    sprintf("dispatch WorkerEvents::RECORDS_WRITE_META for %s.%s", $record->getDataboxId(), $record->getRecordId())
+                ), FILE_APPEND | LOCK_EX);
+
                 $this->app['dispatcher']->dispatch(WorkerEvents::RECORDS_WRITE_META,
                     new RecordsWriteMetaEvent([$record->getRecordId()], $record->getDataboxId()));
             }
@@ -245,6 +291,10 @@ class LazaretManipulator
             // no-op
         }
 
+        file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("return from laaret/add")
+        ), FILE_APPEND | LOCK_EX);
+
         return $ret;
     }
 

lib/Alchemy/Phrasea/Model/Repositories/WorkerRunningJobRepository.php

@@ -45,6 +45,7 @@ class WorkerRunningJobRepository extends EntityRepository
      *
      * rule :
      * - if someone is already working on the file, we can't write
+     * - if someone is building subdefs, we can't write on tne document
      *
      * @param array $payload
      * @return int | null       workerRunningJobId
@@ -54,8 +55,14 @@ class WorkerRunningJobRepository extends EntityRepository
         $this->reconnect();
         $cnx = $this->getEntityManager()->getConnection()->getWrappedConnection();
 
+        // if someone is already working on the file, we can't write
         $sqlclause = "(`work_on` = " . $cnx->quote($payload['subdefName']) . ")";
 
+        if($payload['subdefName'] === "document") {
+            // if someone is building subdefs, we can't write on tne document
+            $sqlclause = "(" . $sqlclause . " OR (`work` = " . $cnx->quote(MessagePublisher::SUBDEF_CREATION_TYPE) . "))";
+        }
+
         return $this->canDoJob($payload, MessagePublisher::WRITE_METADATAS_TYPE, $sqlclause);
     }
 
@@ -78,10 +85,9 @@ class WorkerRunningJobRepository extends EntityRepository
 
         $databoxId      = $payload['databoxId'];
         $recordId       = $payload['recordId'];
-        $subdefName     = $payload['subdefName'];
 
         file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
-            sprintf('canDoJob("%s") for %s.%s.%s ?', $jobType, $databoxId, $recordId, $subdefName)
+            sprintf('canDoJob("%s") for %s.%s ?', $jobType, $databoxId, $recordId)
         ), FILE_APPEND | LOCK_EX);
 
         // first protect sql by a critical section
@@ -116,7 +122,7 @@ class WorkerRunningJobRepository extends EntityRepository
                 }
                 else {
                     file_put_contents(dirname(__FILE__) . '/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
-                        sprintf("!!! FAILED select on %s.%s.%s because (%s)", $databoxId, $recordId, $subdefName, $stmt->errorCode())
+                        sprintf("!!! FAILED select on %s.%s because (%s)", $databoxId, $recordId, $stmt->errorCode())
                     ), FILE_APPEND | LOCK_EX);
                 }
                 $stmt->closeCursor();
@@ -127,7 +133,7 @@ class WorkerRunningJobRepository extends EntityRepository
                 }
                 else {
                     file_put_contents(dirname(__FILE__) . '/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
-                        sprintf("job %s (id=%s) already running on %s.%s.%s", $row['work'], $row['id'], $databoxId, $recordId, $subdefName)
+                        sprintf("job %s (id=%s) already running on %s.%s", $row['work'], $row['id'], $databoxId, $recordId)
                     ), FILE_APPEND | LOCK_EX);
                 }
 
@@ -137,13 +143,13 @@ class WorkerRunningJobRepository extends EntityRepository
                 $cnx->rollBack();
 
                 file_put_contents(dirname(__FILE__) . '/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
-                    sprintf("!!! FAILED in transaction to select/create on %s.%s.%s because (%s)", $databoxId, $recordId, $subdefName, $e->getMessage())
+                    sprintf("!!! FAILED in transaction to select/create on %s.%s because (%s)", $databoxId, $recordId, $e->getMessage())
                 ), FILE_APPEND | LOCK_EX);
             }
         }
         else {
             file_put_contents(dirname(__FILE__) . '/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
-                sprintf("!!! FAILED to create transaction to select/create on %s.%s.%s", $databoxId, $recordId, $subdefName)
+                sprintf("!!! FAILED to create transaction to select/create on %s.%s", $databoxId, $recordId)
             ), FILE_APPEND | LOCK_EX);
         }
 
@@ -270,14 +276,14 @@ class WorkerRunningJobRepository extends EntityRepository
             if ($cnx->exec($sql) > 0) {
                 // affected rows is 1 since by definition this key is unique
                 file_put_contents(dirname(__FILE__) . '/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
-                    sprintf("!!! old mutex for %s.%s deleted (!!! SHOULD NOT HAPPEN !!!)", $databoxId, $recordId)
+                    sprintf("!!! old mutex for %s.%s deleted !!! SHOULD NOT HAPPEN !!!", $databoxId, $recordId)
                 ), FILE_APPEND | LOCK_EX);
             }
         }
         catch(Exception $e) {
             // here something went very wrong, like sql death
             file_put_contents(dirname(__FILE__) . '/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
-                sprintf("!!! FAILED while trying to delete old mutex for %s.%s (!!! SHOULD NOT HAPPEN !!!)", $databoxId, $recordId)
+                sprintf("!!! FAILED while trying to delete old mutex for %s.%s because (%s) !!! SHOULD NOT HAPPEN !!!", $e->getMessage(), $databoxId, $recordId)
             ), FILE_APPEND | LOCK_EX);
 
             return false; // we could choose to continue, but if we end up here... better to stop
@@ -303,11 +309,12 @@ class WorkerRunningJobRepository extends EntityRepository
 
                 if(($a = $cnx->exec($sql)) === 1) {
 
+                    $mutexId = $cnx->lastInsertId();
                     file_put_contents(dirname(__FILE__) . '/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
-                        sprintf("getMutex tryout %s for %s.%s OK", $tryout, $databoxId, $recordId)
+                        sprintf("getMutex tryout %s for %s.%s OK, returning mutex (id=%s)", $tryout, $databoxId, $recordId, $mutexId)
                     ), FILE_APPEND | LOCK_EX);
 
-                    return $cnx->lastInsertId();
+                    return $mutexId;
                 }
 
                 throw new Exception(sprintf("inserting mutex should return 1 row affected, got %s", $a));
@@ -517,19 +524,22 @@ class WorkerRunningJobRepository extends EntityRepository
 
     public function reconnect()
     {
-//        if(!$this->getEntityManager()->isOpen()) {
-//            file_put_contents(dirname(__FILE__) . '/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
-//                sprintf("recreate _em")
-//            ), FILE_APPEND | LOCK_EX);
-//            $this->_em = $this->_em->create(
-//                $this->_em->getConnection(),
-//                $this->_em->getConfiguration(),
-//                $this->_em->getEventManager()
-//            );
-//        }
         if($this->_em->getConnection()->ping() === false) {
+            file_put_contents(dirname(__FILE__) . '/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                sprintf("!!!! reconnect-ping returned false, calling \"connect()\".")
+            ), FILE_APPEND | LOCK_EX);
             $this->_em->getConnection()->close();
             $this->_em->getConnection()->connect();
         }
+        if(!$this->getEntityManager()->isOpen()) {
+            file_put_contents(dirname(__FILE__) . '/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                sprintf("!!!! entity manager closed, recreating.")
+            ), FILE_APPEND | LOCK_EX);
+            $this->_em = $this->_em->create(
+                $this->_em->getConnection(),
+                $this->_em->getConfiguration(),
+                $this->_em->getEventManager()
+            );
+        }
     }
 }

lib/Alchemy/Phrasea/WorkerManager/Subscriber/RecordSubscriber.php

@@ -152,6 +152,10 @@ class RecordSubscriber implements EventSubscriberInterface
         $databoxId = $event->getDataboxId();
         $recordIds = $event->getRecordIds();
 
+        file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("handle RECORDS_WRITE_META for %s.[%s]", $databoxId, join(',', $recordIds))
+        ), FILE_APPEND | LOCK_EX);
+
         foreach ($recordIds as $recordId) {
             $mediaSubdefRepository = $this->getMediaSubdefRepository($databoxId);
             $mediaSubdefs = $mediaSubdefRepository->findByRecordIdsAndNames([$recordId]);
@@ -173,6 +177,10 @@ class RecordSubscriber implements EventSubscriberInterface
                     ];
 
                     if ($subdef->is_physically_present()) {
+                        file_put_contents(dirname(__FILE__).'/../../../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                            sprintf("q-publish  WRITE_METADATAS_TYPE for %s.%s.%s", $databoxId, $recordId, $subdef->get_name())
+                        ), FILE_APPEND | LOCK_EX);
+
                         $this->messagePublisher->publishMessage($payload, MessagePublisher::WRITE_METADATAS_TYPE);
                     }
                     else {

lib/classes/record/adapter.php

@@ -1140,6 +1140,10 @@ class record_adapter implements RecordInterface, cache_cacheableInterface
      */
     public function set_metadatas(array $metadatas, $force_readonly = false)
     {
+        file_put_contents(dirname(__FILE__).'/../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("into set_metadatas for record %s.%s", $this->getDataboxId(), $this->getRecordId())
+        ), FILE_APPEND | LOCK_EX);
+
         $databox_descriptionStructure = $this->getDatabox()->get_meta_structure();
 
         foreach ($metadatas as $param) {
@@ -1163,8 +1167,17 @@ class record_adapter implements RecordInterface, cache_cacheableInterface
         unset($xml);
 
         $this->write_metas();
+
+        file_put_contents(dirname(__FILE__).'/../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("dispatch event RecordEvents::METADATA_CHANGED for record %s.%s", $this->getDataboxId(), $this->getRecordId())
+        ), FILE_APPEND | LOCK_EX);
+
         $this->dispatch(RecordEvents::METADATA_CHANGED, new MetadataChangedEvent($this));
 
+        file_put_contents(dirname(__FILE__).'/../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("return from set_metadata for record %s.%s", $this->getDataboxId(), $this->getRecordId())
+        ), FILE_APPEND | LOCK_EX);
+
         return $this;
     }
 
@@ -1669,6 +1682,10 @@ class record_adapter implements RecordInterface, cache_cacheableInterface
      */
     public static function createFromFile(File $file, Application $app)
     {
+        file_put_contents(dirname(__FILE__).'/../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("into createFromFile")
+        ), FILE_APPEND | LOCK_EX);
+
         $collection = $file->getCollection();
 
         $record = self::_create(
@@ -1684,6 +1701,10 @@ class record_adapter implements RecordInterface, cache_cacheableInterface
             $pathhd = $filesystem->generateDataboxDocumentBasePath($databox);
             $newname = $filesystem->generateDocumentFilename($record, $file->getFile());
 
+            file_put_contents(dirname(__FILE__).'/../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                sprintf("copy \"%s\" to \"%s\"", $file->getFile()->getRealPath(), $pathhd . $newname)
+            ), FILE_APPEND | LOCK_EX);
+
             $filesystem->copy($file->getFile()->getRealPath(), $pathhd . $newname);
 
             $media = $app->getMediaFromUri($pathhd . $newname);
@@ -1727,6 +1748,10 @@ class record_adapter implements RecordInterface, cache_cacheableInterface
      */
     private static function _create(collection $collection, Application $app, File $file=null)
     {
+        file_put_contents(dirname(__FILE__).'/../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("into _create")
+        ), FILE_APPEND | LOCK_EX);
+
         $databox = $collection->get_databox();
 
         $sql = "INSERT INTO record"
@@ -1749,6 +1774,10 @@ class record_adapter implements RecordInterface, cache_cacheableInterface
 
         $record_id = $connection->lastInsertId();
 
+        file_put_contents(dirname(__FILE__).'/../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+            sprintf("sql record::inserted %s", $record_id)
+        ), FILE_APPEND | LOCK_EX);
+
         $record = new self($app, $databox->get_sbas_id(), $record_id);
 
         try {
@@ -1765,6 +1794,12 @@ class record_adapter implements RecordInterface, cache_cacheableInterface
                 ':final'     => $collection->get_coll_id(),
             ]);
             $stmt->closeCursor();
+
+            file_put_contents(dirname(__FILE__).'/../../../logs/trace.txt', sprintf("%s [%s] : %s (%s); %s\n", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+                sprintf("sql log_docs::inserted add %s", $record_id)
+            ), FILE_APPEND | LOCK_EX);
+
+
         }
         catch (\Exception $e) {
             $record = null;