fix : no writemeta on doc while building subdef

add traces

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

@@ -50,7 +50,7 @@ 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", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+        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);
 

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

@@ -60,7 +60,7 @@ class UUID extends AbstractChecker
             $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", (date('Y-m-d\TH:i:s')), getmypid(), __FILE__, __LINE__,
+        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);
 

lib/Alchemy/Phrasea/Border/File.php

@@ -94,7 +94,7 @@ class File
     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 with generate=%s, write=%s ; this->uuid=%s", $generate?'true':'false', $write?'true':'false', $this->uuid ?:'null')
+            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) {
@@ -166,8 +166,23 @@ 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
             }
         }
@@ -215,15 +230,28 @@ 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")
+            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 from getSha256")
+            sprintf("return sha256 %s", $this->sha256 ?: 'null')
         ), FILE_APPEND | LOCK_EX);
 
         return $this->sha256;

lib/Alchemy/Phrasea/Border/Manager.php

@@ -21,6 +21,7 @@ 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;
@@ -145,6 +146,10 @@ class Manager
 
             $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;
@@ -304,7 +309,7 @@ class Manager
         $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", $element->getRecordId())
+            sprintf("created %s.%s", $element->getDataboxId(), $element->getRecordId())
         ), FILE_APPEND | LOCK_EX);
 
 
@@ -376,7 +381,9 @@ class Manager
             sprintf("calling replaceMetadata")
         ), FILE_APPEND | LOCK_EX);
 
-        $this->app['phraseanet.metadata-setter']->replaceMetadata($newMetadata, $element);
+        /** @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));
@@ -397,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(
@@ -449,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/Metadata/PhraseanetMetadataSetter.php

@@ -43,7 +43,7 @@ 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", $record->getRecordId())
+            sprintf("replaceMetadata for %s.%s", $record->getDataboxId(), $record->getRecordId())
         ), FILE_APPEND | LOCK_EX);
 
         $metaStructure = $this->repository->find($record->getDataboxId())->get_meta_structure()->get_elements();
@@ -92,16 +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 RECORDS_WRITE_META for %s.%s", $record->getDataboxId(), $record->getRecordId())
+                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,15 +247,27 @@ 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 RECORDS_WRITE_META for %s.%s", $record->getDataboxId(), $record->getRecordId())
+                    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,
@@ -249,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);
     }
 
@@ -269,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
@@ -302,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));
@@ -516,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/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;
     }