logging

app.py

@@ -27,7 +27,7 @@ from graph import graph, model  # noqa
 
 FOLLOWUP_QUESTION_NUMBER = 3
 TRIM_MESSAGE_LENGTH = 16  # Includes tool messages
-USER_INPUT_MAX_LENGTH = 10000  # Characters
+USER_INPUT_MAX_LENGTH = 10001  # Characters
 set_verbose(True)
 set_debug(True)
 
@@ -316,18 +316,26 @@ def find_story_files(idml_package, tag_patterns):
     Returns:
         dict: Mapping of tag patterns to story files
     """
+    logger.info(f"Searching for {len(tag_patterns)} tag patterns in IDML files")
     compiled_patterns = {pattern: re.compile(pattern) for pattern in tag_patterns}
     tag_to_story = {pattern: [] for pattern in tag_patterns}
     stories = [name for name in idml_package.namelist() if name.startswith("Stories/")]
 
+    logger.info(f"Found {len(stories)} story files in IDML package")
+
     for story_path in stories:
         try:
             content = idml_package.open(story_path).read().decode("utf-8")
             for pattern, regex in compiled_patterns.items():
                 if regex.search(content):
+                    logger.info(f"Found pattern '{pattern}' in {story_path}")
                     tag_to_story[pattern].append(story_path)
         except Exception as e:
-            print(f"Error reading {story_path}: {e}")
+            logger.error(f"Error reading {story_path}: {e}")
+
+    # Log summary of matches
+    for pattern, story_files in tag_to_story.items():
+        logger.info(f"Pattern '{pattern}' found in {len(story_files)} story files")
 
     return tag_to_story
 
@@ -344,12 +352,18 @@ def replace_content(xml_content, tag_pattern, replacements):
     Returns:
         str: Updated XML content
     """
+    logger.info(
+        f"Replacing content with pattern '{tag_pattern}' using {len(replacements)} replacements"
+    )
+
     tags = re.finditer(tag_pattern, xml_content)
     tag_positions = [(m.start(), m.end()) for m in tags]
 
     if not tag_positions:
+        logger.warning(f"No tags found with pattern '{tag_pattern}' in XML content")
         return xml_content
 
+    logger.info(f"Found {len(tag_positions)} matching tags to replace")
     content_chars = list(xml_content)
 
     for i, (start, end) in enumerate(reversed(tag_positions)):
@@ -358,20 +372,31 @@ def replace_content(xml_content, tag_pattern, replacements):
         if index < len(replacements):
             # Replace with actual data
             new_content = f"<Content>{replacements[index]}</Content>"
+            logger.info(
+                f"Replacing tag at position {start}-{end} with content: {new_content[:50]}..."
+            )
             content_chars[start:end] = new_content
         else:
             br_pattern = r"\s*<Br />"
             br_match = re.search(br_pattern, "".join(content_chars[end : end + 20]))
             if br_match:
+                logger.info(
+                    f"Removing tag at position {start}-{end} with following line break"
+                )
                 del content_chars[start : end + br_match.end()]
             else:
+                logger.info(f"Removing tag at position {start}-{end}")
                 del content_chars[start:end]
 
     if len(replacements) > len(tag_positions) and tag_positions:
         last_pos = tag_positions[-1][1]
+        logger.info(
+            f"Adding {len(replacements) - len(tag_positions)} additional replacements after position {last_pos}"
+        )
 
         for item in replacements[len(tag_positions) :]:
             insert_content = f"\n<Content>{item}</Content>\n<Br />"
+            logger.info(f"Inserting new content: {insert_content[:50]}...")
             content_chars.insert(last_pos, insert_content)
             last_pos += len(insert_content)
 
@@ -388,6 +413,9 @@ def create_replacements_from_metrics(metrics_data):
     Returns:
         dict: Mapping of tag patterns to replacement values
     """
+    logger.info(
+        f"Creating replacements from metrics: {json.dumps(metrics_data, default=str)}"
+    )
     # Define mappings between metrics keys and IDML tag patterns
     replacements = {
         # Project Description
@@ -422,6 +450,15 @@ def create_replacements_from_metrics(metrics_data):
         ],
     }
 
+    # Create a simplified version of replacements for logging
+    simplified_replacements = {}
+    for k, v in replacements.items():
+        if isinstance(v, list) and len(v) > 0:
+            simplified_replacements[k] = v
+
+    logger.info(
+        f"Generated replacements: {json.dumps(simplified_replacements, default=str)}"
+    )
     return replacements
 
 
@@ -436,6 +473,7 @@ async def update_idml_content(idml_path, replacements_json):
     Returns:
         str: Path to the updated IDML file
     """
+    logger.info(f"Starting update_idml_content with file: {idml_path}")
     # Parse JSON if it's a string
     if isinstance(replacements_json, str):
         replacements = json.loads(replacements_json)
@@ -444,89 +482,134 @@ async def update_idml_content(idml_path, replacements_json):
 
     # Get the directory where app.py is located
     app_dir = os.path.dirname(os.path.abspath(__file__))
+    logger.info(f"App directory: {app_dir}")
 
     # Create a temporary directory
     with tempfile.TemporaryDirectory() as temp_dir:
+        logger.info(f"Created temporary directory: {temp_dir}")
         # Create a copy of the IDML file to work with
         temp_idml = os.path.join(temp_dir, "temp.idml")
-        shutil.copy2(idml_path, temp_idml)
-
-        with idml.IDMLPackage(temp_idml) as working_idml:
-            # Find all story files containing our tags
-            tag_patterns = list(replacements.keys())
-            tag_to_story = find_story_files(working_idml, tag_patterns)
+        try:
+            shutil.copy2(idml_path, temp_idml)
+            logger.info(f"Copied IDML file to: {temp_idml}")
+        except Exception as e:
+            logger.error(f"Failed to copy IDML file: {str(e)}")
+            raise
 
-            # Extract the IDML
-            extract_dir = os.path.join(temp_dir, "extracted")
-            os.makedirs(extract_dir, exist_ok=True)
-            working_idml.extractall(extract_dir)
+        try:
+            with idml.IDMLPackage(temp_idml) as working_idml:
+                # Find all story files containing our tags
+                tag_patterns = list(replacements.keys())
+                logger.info(f"Looking for {len(tag_patterns)} tag patterns in IDML")
+                tag_to_story = find_story_files(working_idml, tag_patterns)
+                logger.info(
+                    f"Found tag patterns in story files: {json.dumps({k: len(v) for k, v in tag_to_story.items()}, default=str)}"
+                )
 
-            # Process each tag pattern
-            for tag_pattern, replacement_values in replacements.items():
-                story_files = tag_to_story.get(tag_pattern, [])
+                # Extract the IDML
+                extract_dir = os.path.join(temp_dir, "extracted")
+                os.makedirs(extract_dir, exist_ok=True)
+                logger.info(f"Extracting IDML to: {extract_dir}")
+                working_idml.extractall(extract_dir)
 
-                if not story_files:
-                    print(
-                        f"Warning: No story files found containing pattern '{tag_pattern}'"
-                    )
-                    continue
+                # Process each tag pattern
+                for tag_pattern, replacement_values in replacements.items():
+                    story_files = tag_to_story.get(tag_pattern, [])
 
-                print(
-                    f"Found pattern '{tag_pattern}' in {len(story_files)} story file(s)"
-                )
+                    if not story_files:
+                        logger.warning(
+                            f"No story files found containing pattern '{tag_pattern}'"
+                        )
+                        continue
 
-                # Update each story file containing this tag
-                for story_path in story_files:
-                    # Read the XML content
-                    with open(
-                        os.path.join(extract_dir, story_path), "r", encoding="utf-8"
-                    ) as f:
-                        xml_content = f.read()
-
-                    # Update the content
-                    updated_content = replace_content(
-                        xml_content, tag_pattern, replacement_values
+                    logger.info(
+                        f"Found pattern '{tag_pattern}' in {len(story_files)} story file(s)"
                     )
 
-                    # Write back the updated content
-                    with open(
-                        os.path.join(extract_dir, story_path), "w", encoding="utf-8"
-                    ) as f:
-                        f.write(updated_content)
-
-            # Create the output path in the same directory as app.py
-            base_name = os.path.splitext(os.path.basename(idml_path))[0]
-            output_filename = (
-                f"{base_name}_filled_{datetime.now().strftime('%Y%m%d%H%M%S')}.idml"
-            )
-            output_path = os.path.join(app_dir, output_filename)
+                    # Update each story file containing this tag
+                    for story_path in story_files:
+                        # Read the XML content
+                        try:
+                            with open(
+                                os.path.join(extract_dir, story_path),
+                                "r",
+                                encoding="utf-8",
+                            ) as f:
+                                xml_content = f.read()
+
+                            # Update the content
+                            updated_content = replace_content(
+                                xml_content, tag_pattern, replacement_values
+                            )
 
-            # Create a new IDML with the updated content
-            shutil.make_archive(output_path, "zip", extract_dir)
-            os.rename(output_path + ".zip", output_path)
+                            # Write back the updated content
+                            with open(
+                                os.path.join(extract_dir, story_path),
+                                "w",
+                                encoding="utf-8",
+                            ) as f:
+                                f.write(updated_content)
+
+                            logger.info(f"Updated content in {story_path}")
+                        except Exception as e:
+                            logger.error(
+                                f"Error processing story file {story_path}: {str(e)}"
+                            )
 
-            print(f"Updated IDML saved to: {output_path}")
-            return output_path
+                # Create the output path in the same directory as app.py
+                base_name = os.path.splitext(os.path.basename(idml_path))[0]
+                output_filename = (
+                    f"{base_name}_filled_{datetime.now().strftime('%Y%m%d%H%M%S')}.idml"
+                )
+                output_path = os.path.join(app_dir, output_filename)
+                logger.info(f"Output IDML will be saved to: {output_path}")
+
+                # Create a new IDML with the updated content
+                try:
+                    logger.info(f"Creating archive from: {extract_dir}")
+                    shutil.make_archive(output_path, "zip", extract_dir)
+                    logger.info(f"Renaming {output_path}.zip to {output_path}")
+                    os.rename(output_path + ".zip", output_path)
+                    logger.info(f"Successfully created IDML: {output_path}")
+                except Exception as e:
+                    logger.error(f"Error creating archive: {str(e)}")
+                    raise
+
+                return output_path
+        except Exception as e:
+            logger.error(f"Error in IDML processing: {str(e)}")
+            raise
 
 
 async def export_idml(graph_state: GraphProcessingState, table_data):
     """Export the current metrics, marketing copy, and table data to IDML file"""
+    logger.info("Starting export_idml function")
     try:
         if "idml_file" not in graph_state:
+            logger.warning("No IDML file uploaded in graph_state")
             return None, "No IDML file uploaded"
 
         if "metrics" not in graph_state or "marketing_copy" not in graph_state:
+            logger.warning("No metrics or marketing copy available in graph_state")
             return None, "No metrics or marketing copy available"
 
+        logger.info(f"IDML file path: {graph_state['idml_file']}")
+        logger.info(
+            f"Table data: {table_data.shape if table_data is not None else None}"
+        )
+
         updated_data = dict(graph_state["metrics"])
+        logger.info(f"Metrics data keys: {updated_data.keys()}")
 
         if table_data is not None and not table_data.empty:
             descriptions = table_data["description"].dropna().tolist()
             descriptions = [
                 desc for desc in descriptions if desc.strip()
             ]  # Remove empty strings
+            logger.info(f"Found {len(descriptions)} descriptions in table data")
         else:
             descriptions = [""]  # If no descriptions, create one empty file
+            logger.warning("No descriptions in table data, using empty description")
 
         # Process each description and create IDML files
         output_paths = []
@@ -534,29 +617,58 @@ async def export_idml(graph_state: GraphProcessingState, table_data):
 
         # Process each file one at a time to avoid race conditions
         for i, text in enumerate(descriptions):
-            if "Project Description" not in text:
-                updated_data["description"] = text
-                print(f"Processing description {i+1}/{len(descriptions)}: {text}")
-                replacements = create_replacements_from_metrics(updated_data)
-                output_path = await update_idml_content(
-                    graph_state["idml_file"], replacements
-                )
-                output_paths.append(output_path)
-                # Brief pause to ensure unique timestamps
-                await asyncio.sleep(1)
+            try:
+                if "Project Description" not in text:
+                    logger.info(
+                        f"Processing description {i+1}/{len(descriptions)}: {text[:100]}..."
+                    )
+                    updated_data["description"] = text
+                    replacements = create_replacements_from_metrics(updated_data)
+
+                    # Check if IDML file exists
+                    if not os.path.exists(graph_state["idml_file"]):
+                        logger.error(
+                            f"IDML file does not exist: {graph_state['idml_file']}"
+                        )
+                        return None, f"IDML file not found: {graph_state['idml_file']}"
+
+                    output_path = await update_idml_content(
+                        graph_state["idml_file"], replacements
+                    )
+
+                    # Verify the output file exists
+                    if os.path.exists(output_path):
+                        logger.info(f"Output file created successfully: {output_path}")
+                        output_paths.append(output_path)
+                    else:
+                        logger.error(f"Output file was not created: {output_path}")
+
+                    # Brief pause to ensure unique timestamps
+                    await asyncio.sleep(1)
+                else:
+                    logger.info(f"Skipping placeholder description {i+1}")
+            except Exception as e:
+                logger.error(f"Error processing description {i+1}: {str(e)}")
+                import traceback
+
+                logger.error(traceback.format_exc())
+
+        logger.info(f"Generated {len(output_paths)} IDML files: {output_paths}")
+
+        if len(output_paths) == 0:
+            logger.warning("No IDML files were generated")
+            return None, "No IDML files were generated. Check the logs for details."
 
-        print(f"Generated {len(output_paths)} IDML files: {output_paths}")
         return output_paths, f"{len(output_paths)} IDML files successfully updated"
     except Exception as e:
         import traceback
 
-        print(f"Error in export_idml: {str(e)}")
-        print(traceback.format_exc())
+        logger.error(f"Error in export_idml: {str(e)}")
+        logger.error(traceback.format_exc())
         return None, f"Error updating IDML: {str(e)}"
 
-        # Create placeholder data for the table
-
 
+# Create placeholder data for the table
 placeholder_data = pd.DataFrame(
     {
         "description": [
@@ -576,7 +688,11 @@ with gr.Blocks(title="Transcript to Marketing Copy", fill_height=True, css=CSS)
     with gr.Row():
         with gr.Column(scale=4):
             chatbot = gr.Chatbot(type="messages", height=700, show_copy_button=True)
-            chatbot.clear(fn=clear, outputs=[gradio_graph_state, uuid_state])
+            try:
+                chatbot.clear(fn=clear, outputs=[gradio_graph_state, uuid_state])
+                logger.info("Successfully set up chatbot.clear event")
+            except Exception as e:
+                logger.error(f"Error setting up chatbot.clear event: {str(e)}")
 
             multimodal = False
             textbox_component = gr.MultimodalTextbox if multimodal else gr.Textbox
@@ -636,23 +752,35 @@ with gr.Blocks(title="Transcript to Marketing Copy", fill_height=True, css=CSS)
                     label="IDML Export Status",
                     interactive=False,
                     lines=2,
-                    visible=False,
+                    visible=True,
                 )
                 idml_output = gr.File(
                     label="Download Updated IDML",
                     file_count="multiple",
                     visible=True,
                 )
-                download_btn.click(
-                    fn=download_csv,
-                    inputs=[table],
-                    outputs=gr.File(label="Download CSV"),
-                )
-                export_idml_btn.click(
-                    fn=export_idml,
-                    inputs=[gradio_graph_state, table],
-                    outputs=[idml_output, idml_status],
-                )
+
+                try:
+                    download_btn.click(
+                        fn=download_csv,
+                        inputs=[table],
+                        outputs=gr.File(label="Download CSV"),
+                    )
+                    logger.info("Successfully set up download_btn.click event")
+                except Exception as e:
+                    logger.error(f"Error setting up download_btn.click event: {str(e)}")
+
+                try:
+                    export_idml_btn.click(
+                        fn=export_idml,
+                        inputs=[gradio_graph_state, table],
+                        outputs=[idml_output, idml_status],
+                    )
+                    logger.info("Successfully set up export_idml_btn.click event")
+                except Exception as e:
+                    logger.error(
+                        f"Error setting up export_idml_btn.click event: {str(e)}"
+                    )
             metrics_display = gr.Textbox(
                 label="Project Metrics", interactive=False, lines=1, scale=1
             )

logging-config.json

@@ -22,7 +22,7 @@
         }
     },
     "root": {
-        "level": "INFO",
+        "level": "DEBUG",
         "handlers": ["console", "file"]
     }
 }