How can I write :::: to the log whenever (and whereever) a macro is called?

Question

I am working on context-based log entries. Each time a selected (patched) macro is called, it should provide its contents along with a meaningful log entry.

"Meaningful" log entry defined:

The following context is given per custom log entry:

• section counter value
• section title
• page number
• file name/path
• line number

This is what I want:

<macro content> (<section counter value>:<section title>:<page number>:<file>:<line number>)

Problems

I have two problems I guess:

1. Dealing with \thetitle when one of these selected macros falls within a sectioning command itself.
2. Getting full value of expanded macro into log as string in case with \myproduct macro.

How I have implemented "meaningful" log entries

• \thetitle get section counter titlesec
• \@currentlabelname get section title titlesec provides \def\@currentlabelname for nameref (I only tested this with straight classes, that is, classes with nobottomtitles)
• \thepage get page LaTeX
• \the\inputlineno get line number LaTeX (refers to lineno in current file when using \input)
• max_print_line=10000 in texmf.cnf to expand max chars per line in log output (irrelevant to this question, but relevant for people who might also want to implement custom logs)

Hopefully I have my facts straight above.

Problem 2 (almost working, typesets fine)

Sometimes my section titles contains macros. This could lead to expansion problems. Also, sometimes the section titles contain the very macro I am tracking, which makes it tricky to use \thetitle in the log entry e.g. \section{About \myproduct{monkey shampoo}} which should yield e.g. MacGyver.monkey shampoo (2:About MacGyver.monkey shampoo:[1]:test.tex:11).

\documentclass{article}
\usepackage{fontspec}% use xelatex
\usepackage{titlesec}% adds \thetitle and \@currentlabelname
\usepackage{currfile}% adds \currfilepath

% Define a couple commands to track
\newcommand\myapp[1]{\textit{#1}}
\newcommand\myproduct[1]{MacGyver.\textit{#1}}% Purposefully made this one contain more text that what is saved in #1

% The following is normally put into separate file as to modularize the application of patches
% Define a context macro as described
\makeatletter
\def\contextinfo{\thetitle:\@currentlabelname:[\thepage]:\currfilepath:\the\inputlineno}
\makeatother
% Apply Patches
\usepackage{regexpatch}
\xapptocmd{\myapp}{\typeout{ ==> #1 (\contextinfo)}}{}{}
\xapptocmd{\myproduct}{\typeout{ ==> #1 (\contextinfo)}}{}{}% <-- I'd rather show MacGyver.monkey shampoo, but unsure how best to implement
% Note: \typeout is always fully expanded due to \write %http://tex.stackexchange.com/a/60976/13552

\begin{document}
\section{Elephant}
\section{Monkey}
\subsection{Bonabo}
\myapp{listmonkeys}
\myproduct{monkey shampoo}
\end{document}

Log Output

See problem 2 above: How can I make "monkey shampoo" be "MacGyver.monkey shampoo" or maybe easier: MacGyver.\textit{monkey shampoo}

 ==> listmonkeys (2.1:Bonabo:[1]:test.tex:34)
 ==> monkey shampoo (2.1:Bonabo:[1]:test.tex:35)

Problem 1 (not working, does not typeset)

See Problem 1 above: How can I deal with the \thetitle, which is defined in titlesec by \gdef\thetitle{\csname the#1\endcsname}%?

\documentclass{article}
\usepackage{fontspec}% use xelatex
\usepackage{titlesec}% adds \thetitle and \@currentlabelname
\usepackage{currfile}% adds \currfilepath

% Define a couple commands to track
\newcommand\myapp[1]{\textit{#1}}
\newcommand\myproduct[1]{MacGyver.\textit{#1}}% Purposefully made this one contain more text that what is saved in #1

% The following is normally put into separate file as to modularize the application of patches
% Define a context macro as described
\makeatletter
\def\contextinfo{\thetitle:\@currentlabelname:[\thepage]:\currfilepath:\the\inputlineno}
\makeatother
% Apply Patches
\usepackage{regexpatch}
\xapptocmd{\myapp}{\typeout{ ==> #1 (\contextinfo)}}{}{}
\xapptocmd{\myproduct}{\typeout{ ==> #1 (\contextinfo)}}{}{}% <-- I'd rather show MacGyver.monkey shampoo, but unsure how best to implement
% Note: \typeout is always fully expanded due to \write %http://tex.stackexchange.com/a/60976/13552

\begin{document}
\section{Elephant \myapp{watcher}}% probably \thetitle has not been set yet, causing error
\section{Monkey \myproduct{monkey shampoo}}
\subsection{Bonabo}
\end{document}

Log Output

! TeX capacity exceeded, sorry [input stack size=5000].

Answer 1

Is this what you want?

\documentclass{article}
\usepackage{fontspec}% use xelatex
\usepackage{titlesec}% adds \thetitle and \@currentlabelname
\usepackage{nameref}
\usepackage{regexpatch}

\usepackage{currfile}% adds \currfilepath


% Define a couple commands to track
\newcommand\myapp[1]{\textit{#1}}
\newcommand\myproduct[1]{MacGyver.\textit{#1}}% Purposefully made this one contain more text that what is saved in #1

% The following is normally put into separate file as to modularize the application of patches
% Define a context macro as described

\makeatletter
\def\contextinfo{\thetitle\space:\@currentlabelname:[\thepage]:\currfilepath:\the\inputlineno}
\DeclareRobustCommand{\WriteToLog}[1]{%
  \gdef\@currentlabelname{#1}\immediate\write-1{ ==> #1 (\contextinfo)}
}
\AtBeginDocument{%
\xapptocmd{\myapp}{\WriteToLog{#1}}{}{}
\xapptocmd{\myproduct}{\WriteToLog{#1}}{}{}
}
\makeatother

\begin{document}
\section{Elephant \myapp{watcher}}\label{foo}% probably \thetitle has not been set yet, causing error
\section{Monkey \myproduct{monkey shampoo}}
\subsection{Bonabo}
\end{document}

Answer 2

A big issue you have to deal with is expandability of content, since you're writing to the terminal. To get around this, I define two versions of your \myapp and \myproduct functions. The regular \myapp and \myproduct are declared to be robust, while \@myapp and \@myproduct are expandable and simplified versions of their counterparts (removing font-related settings like \textit, for example).

I also avoided the complexities of titlesec and construct my own \thenumber (that contains the section number) and \thetitle (that contains the section title using the simplified versions of \@myapp and/or \@myproduct).

\documentclass{article}

\usepackage{currfile}% adds \currfilepath

% Define a couple commands to track
\DeclareRobustCommand{\myapp}[1]{\textit{#1}}
\DeclareRobustCommand{\myproduct}[1]{MacGyver.\textit{#1}}
\makeatletter
\newcommand{\@myapp}[1]{#1}
\newcommand{\@myproduct}[1]{MacGyver.#1}
\makeatother

% The following is normally put into separate file as to modularize the application of patches
% Define a context macro as described
\def\contextinfo{\thenumber:\thetitle:[\thepage]:\currfilepath:\the\inputlineno}

% Apply Patches
\usepackage{regexpatch}
\xapptocmd{\myapp}{\typeout{ ==> #1 (\contextinfo)}}{}{}
\xapptocmd{\myproduct}{\typeout{ ==> #1 (\contextinfo)}}{}{}% <-- I'd rather show MacGyver.monkey shampoo, but unsure how best to implement
% Note: \typeout is always fully expanded due to \write %http://tex.stackexchange.com/a/60976/13552

%\usepackage{xparse}% Loaded by regexpatch
\let\oldsection\section
\makeatletter
\RenewDocumentCommand{\section}{s o m}{%
  \begingroup
  % Extract the counter representation
  \stepcounter{section}%
  \xdef\thenumber{\thesection}%
  \addtocounter{section}{-1}%
  % Temporarily change \myapp and \myproduct to be expandable and ordinary
  \let\myapp\@myapp
  \let\myproduct\@myproduct
  % Extract the title with possible \myapp and \myproduct (now ordinary/expandable)
  \protected@xdef\thetitle{#3}%
  \endgroup
  % Regular section
  \IfBooleanTF{#1}
    {\oldsection*{#3}}
    {\IfValueTF{#2}
       {\oldsection[#2]{#3}}
       {\oldsection{#3}}}
}
\makeatother

\begin{document}

\section{Elephant \myapp{watcher}}% probably \thetitle has not been set yet, causing error
\section{About \myproduct{monkey shampoo}}
\subsection{Bonabo}

\end{document}

The .log outputs

 ==> watcher (1:Elephant watcher:[1]:test.tex:48)
 ==> monkey shampoo (2:About MacGyver.monkey shampoo:[1]:test.tex:49)

Answer 3

"Macro Tracker" Solution update 2016-07-12

Based on Werner's code, I came up with a nice logging solution.

On the journey to producing a clean log output:

##############################################################################
  Document Diagnostics
##############################################################################
Main File: logs.tex
Page Count: 2
xparsemacro
##############################################################################
--BEGIN-----------------------------------------------------------------------
==> pre-section example (::logs.tex:[1]:144)
==> post-section example (1:Section:logs.tex:[1]:147)
==> post-section example (1.1:Subsection:logs.tex:[1]:150)
==> post-section example (1.1.1:Subsubsection:logs.tex:[1]:153)
==> post-section example (1.1.1.1:Paragraph:logs.tex:[1]:156)
==> in-section call (2:\xparsemacro {in-section call}:logs.tex:[1]:159)
--END-------------------------------------------------------------------------

The code works best for simple, single,-input macros used as tags that might be scattered throughout your text. Also, the log looks nicer with the environment variable max_print_line set to some higher number than 79. e.g. export max_print_line=1000 In my /usr/local/texlive/2016/texmf-dist/web2c/texmf.cnf file, I commented out

770 %error_line = 79
771 %half_error_line = 50
772 %max_print_line = 79

and added them to /usr/local/texlive/2016/texmf.cnf

 11 error_line = 254
 12 half_error_line = 238
 13 max_print_line = 1000

How to use

1. Define single-input (#1) macros with xparse's \NewDocumentCommand (Note that using \newcommand can cause recursive calls when they contain formatting macros like \texttt)
2. Add macro to list of tracked macros \doforeach{} without slash

Experimental Code

\listfiles
\documentclass{article}
\usepackage{regexpatch}
\usepackage{xparse}
\usepackage{etoolbox} % define \do
\usepackage{atveryend} % define \AtEndAfterFileList
\usepackage{currfile} % define \currfilepath
% --------------------------------------------------------------------------------------------------
% My Macros (Variable Placeholders)
%
\newcommand\latexmacro[1]{#1}
\newcommand\latexmacrott[1]{\texttt{latex}.#1}
\DeclareRobustCommand{\latexrobusttt}[1]{\texttt{latexrobust}.#1}
\NewDocumentCommand{\xparsemacro}{m}{#1}
\NewDocumentCommand{\xparsemacrott}{m}{\texttt{xparse}.#1}
% --------------------------------------------------------------------------------------------------
% Log Delimiters
%
\catcode`#=12 % Define out log output delimiter lines using # as catcode 12 instead of 6
  \newcommand{\macloglineL}{##############################################################################}
  \newcommand{\macloglineB}{--BEGIN-----------------------------------------------------------------------}
  \newcommand{\macloglineE}{--END-------------------------------------------------------------------------}
\catcode`#=6
% --------------------------------------------------------------------------------------------------
% Initialize Variables and Define Context-specific log entry
%
\def\currnum{}% initialize (for when section not yet typeset)
\def\currtitle{}% initialize (for when section not yet typeset)
\def\contextinfo{\currnum:\currtitle:\currfilepath:[\thepage]:\the\inputlineno}
% --------------------------------------------------------------------------------------------------
% Create loop macro that supports macros as items
%
\makeatletter
\newcommand\doforeach[2]{\renewcommand\do[1]{#2}\docsvlist{#1}}% Needs etoolbox http://tex.stackexchange.com/questions/318875/how-can-i-loop-through-macros-with-foreach-and-pass-them-to-xapptocmd 
% -----------------------------------------------------------------------------------------------
% Make Document Diagnostics Header
%
\def\docdiagnosticsheader{%
\typeout{%
\macloglineL
^^J%
\space\space Document Diagnostics
^^J%
\macloglineL%
^^J%
Main File: \jobname.tex
^^J%
Page Count: \thepage
}
}%
\AtEndAfterFileList{\docdiagnosticsheader}
% Patch loop (syntax: \doforeach{macro,macro,macro}{what to do for each item})
% Patches tag macros
%
\doforeach{latexmacro,latexmacrott,latexrebusttt,xparsemacro,xparsemacrott}{% macro names wmacout slashes
  \expandafter\ifx\csname #1-tracker\endcsname\relax
    % does not exist, so create it
    \expandafter\def\csname #1-tracker\endcsname{^^J^^J #1 ^^J\macloglineL^^J\macloglineB}
  \else
    % exists, do nothing
  \fi
  \expandafter\xapptocmd\csname#1\endcsname{\expandafter\protected@xdef\csname #1-tracker\endcsname{\unexpanded\expandafter\expandafter\expandafter{\csname #1-tracker\endcsname}^^J==> \unexpanded{##1}           (\contextinfo)}}{\typeout{MACMessage: Successfully patched #1}}{\typeout{MACWarning: Failed to patch #1}}% 2 \expandafter needed, yet 3 are here because one is just to prep the \csname token.
\AtEndAfterFileList{\expandafter\typeout{\csname #1-tracker\endcsname^^J\macloglineE}}% Uncomment to enable tracking in log output
}%
\makeatother
% --------------------------------------------------------------------------------------------------
% The following temporarily redefine sectioning commands to extract titleno and title as \currnum and \currtitle, respectively for \contextinfo
%
\let\oldsection\section%  Redefine section to grab number + title when tracking macros
\makeatletter
\RenewDocumentCommand{\section}{s o m}{%
  \begingroup
  \stepcounter{section}% Extract the counter representation
  \xdef\currnum{\thesection}%
  \addtocounter{section}{-1}%
  \protected@xdef\currtitle{#3}% Extract the title wmac possible tracked macros
  \endgroup
  \IfBooleanTF{#1}% Regular section
    {\oldsection*{#3}}
    {\IfValueTF{#2}
       {\oldsection[#2]{#3}}
       {\oldsection{#3}}}
}
\makeatother
\let\oldsubsection\subsection%  Redefine section to grab number + title when tracking macros
\makeatletter
\RenewDocumentCommand{\subsection}{s o m}{%
  \begingroup
  \stepcounter{subsection}% Extract the counter representation
  \xdef\currnum{\thesubsection}%
  \addtocounter{subsection}{-1}% Restore for normal subsection
  \protected@xdef\currtitle{#3}% Extract the title wmac possible tracked macros
  \endgroup
  \IfBooleanTF{#1}% Regular section
    {\oldsubsection*{#3}}
    {\IfValueTF{#2}
       {\oldsubsection[#2]{#3}}
       {\oldsubsection{#3}}}
}
\makeatother
\makeatletter
\RenewDocumentCommand{\subsubsection}{s o m}{%
  \begingroup
  \stepcounter{subsubsection}% Extract the counter representation
  \xdef\currnum{\thesubsubsection}%
  \addtocounter{subsubsection}{-1}% Restore for normal subsection
  \protected@xdef\currtitle{#3}% Extract the title wmac possible tracked macros
  \endgroup
  \IfBooleanTF{#1}% Regular section
    {\oldsubsubsection*{#3}}
    {\IfValueTF{#2}
       {\oldsubsubsection[#2]{#3}}
       {\oldsubsubsection{#3}}}
}
\makeatother
\let\oldparagraph\paragraph%  Redefine section to grab number + title when tracking macros
\makeatletter
\RenewDocumentCommand{\paragraph}{s o m}{%
  \begingroup
  \stepcounter{paragraph}% Extract the counter representation
  \xdef\currnum{\theparagraph}%
  \addtocounter{paragraph}{-1}% Restore for normal subsection
  \protected@xdef\currtitle{#3}% Extract the title wmac possible tracked macros
  \endgroup
  \IfBooleanTF{#1}% Regular section
    {\oldparagraph*{#3}}
    {\IfValueTF{#2}
       {\oldparagraph[#2]{#3}}
       {\oldparagraph{#3}}}
}
\makeatother
\begin{document}
\latexmacro{pre-section example}
\xparsemacro{pre-section example}
\section{Section}
\latexmacro{post-section example}
\xparsemacro{post-section example}
\subsection{Subsection}
\latexmacro{post-section example}
\xparsemacro{post-section example}
\subsubsection{Subsubsection}
\latexmacro{post-section example}
\xparsemacro{post-section example}
\paragraph{Paragraph}
\latexmacro{post-section example}
\xparsemacro{post-section example}
%\section{\latexmacrott{in-section call}}
%\section{\latexrebusttt{in-section call}}
\section{\xparsemacro{in-section call}}
\section{\xparsemacrott{in-section call}}
%\subsection{\latexmacro{in-subsection call}\xparsemacro{in-subsection call}}
%\subsubsection{\latexmacro{in-subsubsection call}\xparsemacro{in-subsubsection call}}
%\paragraph{\latexmacro{in-paragraph call}\xparsemacro{in-paragraph call}}
\end{document}