Expand and improve the output log in Session-Management

in dependency of tdf#104101

Change-Id: I799f81adf4e4751fb505c84aa075363acf70f5a7
Reviewed-on: https://gerrit.libreoffice.org/33034
Reviewed-by: Samuel Mehrbrodt <Samuel.Mehrbrodt@cib.de>
Tested-by: Samuel Mehrbrodt <Samuel.Mehrbrodt@cib.de>

2 files changed, 161 insertions, 37 deletions

diff --git a/vcl/source/app/session.cxx b/vcl/source/app/session.cxx
index 9ad31af03771..2dc15b157b1c 100644
--- a/vcl/source/app/session.cxx
+++ b/vcl/source/app/session.cxx
@@ -101,12 +101,16 @@ VCLSession::VCLSession()
           m_bInteractionDone( false ),
           m_bSaveDone( false )
 {
+    SAL_INFO("vcl.se", "VCLSession::VCLSession" );
+
     if (m_xSession)
         m_xSession->SetCallback( SalSessionEventProc, this );
 }
 
 void VCLSession::callSaveRequested( bool bShutdown )
 {
+    SAL_INFO("vcl.se", "VCLSession::callSaveRequested" );
+
     std::list< Listener > aListeners;
     {
         osl::MutexGuard aGuard( m_aMutex );
@@ -127,7 +131,10 @@ void VCLSession::callSaveRequested( bool bShutdown )
         m_bInteractionRequested = m_bInteractionGranted = !m_xSession;
 
         // answer the session manager even if no listeners available anymore
-        SAL_WARN_IF(  aListeners.empty(), "vcl.app", "saveRequested but no listeners !" );
+        SAL_WARN_IF(  aListeners.empty(), "vcl.se", "saveRequested but no listeners !" );
+
+        SAL_INFO("vcl.se.debug", "  aListeners.empty() = " << (aListeners.empty() ? "true" : "false") <<
+                                 ", bShutdown = " << (bShutdown ? "true" : "false"));
         if( aListeners.empty() )
         {
             if (m_xSession)
@@ -143,6 +150,8 @@ void VCLSession::callSaveRequested( bool bShutdown )
 
 void VCLSession::callInteractionGranted( bool bInteractionGranted )
 {
+    SAL_INFO("vcl.se", "VCLSession::callInteractionGranted" );
+
     std::list< Listener > aListeners;
     {
         osl::MutexGuard aGuard( m_aMutex );
@@ -154,7 +163,10 @@ void VCLSession::callInteractionGranted( bool bInteractionGranted )
         m_bInteractionGranted = bInteractionGranted;
 
         // answer the session manager even if no listeners available anymore
-        SAL_WARN_IF( aListeners.empty(), "vcl.app", "interactionGranted but no listeners !" );
+        SAL_WARN_IF(  aListeners.empty(), "vcl.se", "interactionGranted but no listeners !" );
+
+        SAL_INFO("vcl.se.debug", "  aListeners.empty() = " << (aListeners.empty() ? "true" : "false") <<
+                                 ", bInteractionGranted = " << (bInteractionGranted ? "true" : "false"));
         if( aListeners.empty() )
         {
             if (m_xSession)
@@ -170,6 +182,8 @@ void VCLSession::callInteractionGranted( bool bInteractionGranted )
 
 void VCLSession::callShutdownCancelled()
 {
+    SAL_INFO("vcl.se", "VCLSession::callShutdownCancelled");
+
     std::list< Listener > aListeners;
     {
         osl::MutexGuard aGuard( m_aMutex );
@@ -186,6 +200,8 @@ void VCLSession::callShutdownCancelled()
 
 void VCLSession::callQuit()
 {
+    SAL_INFO("vcl.se", "VCLSession::callQuit");
+
     std::list< Listener > aListeners;
     {
         osl::MutexGuard aGuard( m_aMutex );
@@ -206,25 +222,31 @@ void VCLSession::callQuit()
 
 void VCLSession::SalSessionEventProc( void* pData, SalSessionEvent* pEvent )
 {
+    SAL_INFO("vcl.se", "VCLSession::SalSessionEventProc");
+
     VCLSession * pThis = static_cast< VCLSession * >( pData );
     switch( pEvent->m_eType )
     {
         case Interaction:
         {
+            SAL_INFO("vcl.se.debug", "  EventProcType = Interaction");
             SalSessionInteractionEvent* pIEv = static_cast<SalSessionInteractionEvent*>(pEvent);
             pThis->callInteractionGranted( pIEv->m_bInteractionGranted );
         }
         break;
         case SaveRequest:
         {
+            SAL_INFO("vcl.se.debug", "  EventProcType = SaveRequest");
             SalSessionSaveRequestEvent* pSEv = static_cast<SalSessionSaveRequestEvent*>(pEvent);
             pThis->callSaveRequested( pSEv->m_bShutdown );
         }
         break;
         case ShutdownCancel:
+            SAL_INFO("vcl.se.debug", "  EventProcType = ShutdownCancel");
             pThis->callShutdownCancelled();
             break;
         case Quit:
+            SAL_INFO("vcl.se.debug", "  EventProcType = Quit");
             pThis->callQuit();
             break;
     }
@@ -232,16 +254,23 @@ void VCLSession::SalSessionEventProc( void* pData, SalSessionEvent* pEvent )
 
 void SAL_CALL VCLSession::addSessionManagerListener( const css::uno::Reference<XSessionManagerListener>& xListener ) throw( RuntimeException, std::exception )
 {
+    SAL_INFO("vcl.se", "VCLSession::addSessionManagerListener" );
+
     osl::MutexGuard aGuard( m_aMutex );
 
+    SAL_INFO("vcl.se.debug", "  m_aListeners.size() = " << m_aListeners.size() );
     m_aListeners.push_back( Listener( xListener ) );
 }
 
 void SAL_CALL VCLSession::removeSessionManagerListener( const css::uno::Reference<XSessionManagerListener>& xListener ) throw( RuntimeException, std::exception )
 {
+    SAL_INFO("vcl.se", "VCLSession::removeSessionManagerListener" );
+
     osl::MutexGuard aGuard( m_aMutex );
 
     std::list< Listener >::iterator it = m_aListeners.begin();
+
+    SAL_INFO("vcl.se.debug", "  m_aListeners.size() = " << m_aListeners.size() );
     while( it != m_aListeners.end() )
     {
         if( it->m_xListener == xListener )
@@ -255,6 +284,10 @@ void SAL_CALL VCLSession::removeSessionManagerListener( const css::uno::Referenc
 
 void SAL_CALL VCLSession::queryInteraction( const css::uno::Reference<XSessionManagerListener>& xListener ) throw( RuntimeException, std::exception )
 {
+    SAL_INFO("vcl.se", "VCLSession::queryInteraction");
+
+    SAL_INFO("vcl.se.debug", "  m_bInteractionGranted = " << (m_bInteractionGranted ? "true" : "false") <<
+                             ", m_bInteractionRequested = "<< (m_bInteractionRequested ? "true" : "false"));
     if( m_bInteractionGranted )
     {
         if( m_bInteractionDone )
@@ -274,6 +307,7 @@ void SAL_CALL VCLSession::queryInteraction( const css::uno::Reference<XSessionMa
     {
         if( it->m_xListener == xListener )
         {
+            SAL_INFO("vcl.se.debug", "  it->m_xListener == xListener");
             it->m_bInteractionRequested = true;
             it->m_bInteractionDone      = false;
         }
@@ -282,6 +316,8 @@ void SAL_CALL VCLSession::queryInteraction( const css::uno::Reference<XSessionMa
 
 void SAL_CALL VCLSession::interactionDone( const css::uno::Reference< XSessionManagerListener >& xListener ) throw( RuntimeException, std::exception )
 {
+    SAL_INFO("vcl.se", "VCLSession::interactionDone");
+
     osl::MutexGuard aGuard( m_aMutex );
     int nRequested = 0, nDone = 0;
     for( std::list< Listener >::iterator it = m_aListeners.begin(); it != m_aListeners.end(); ++it )
@@ -295,6 +331,9 @@ void SAL_CALL VCLSession::interactionDone( const css::uno::Reference< XSessionMa
         if( it->m_bInteractionDone )
             nDone++;
     }
+
+    SAL_INFO("vcl.se.debug", "  nDone = " << nDone <<
+                             ", nRequested =" << nRequested);
     if( nDone == nRequested && nDone > 0 )
     {
         m_bInteractionDone = true;
@@ -305,6 +344,8 @@ void SAL_CALL VCLSession::interactionDone( const css::uno::Reference< XSessionMa
 
 void SAL_CALL VCLSession::saveDone( const css::uno::Reference< XSessionManagerListener >& xListener ) throw( RuntimeException, std::exception )
 {
+    SAL_INFO("vcl.se", "VCLSession::saveDone");
+
     osl::MutexGuard aGuard( m_aMutex );
 
     bool bSaveDone = true;
@@ -316,6 +357,8 @@ void SAL_CALL VCLSession::saveDone( const css::uno::Reference< XSessionManagerLi
         if( ! it->m_bSaveDone )
             bSaveDone = false;
     }
+
+    SAL_INFO("vcl.se.debug", "  bSaveDone = " << (bSaveDone ? "true" : "false"));
     if( bSaveDone )
     {
         m_bSaveDone = true;
@@ -326,10 +369,14 @@ void SAL_CALL VCLSession::saveDone( const css::uno::Reference< XSessionManagerLi
 
 sal_Bool SAL_CALL VCLSession::cancelShutdown() throw( RuntimeException, std::exception )
 {
+    SAL_INFO("vcl.se", "VCLSession::cancelShutdown");
+
     return m_xSession && m_xSession->cancelShutdown();
 }
 
 void VCLSession::disposing() {
+    SAL_INFO("vcl.se", "VCLSession::disposing");
+
     std::list<Listener> list;
     {
         osl::MutexGuard g(m_aMutex);
@@ -339,8 +386,9 @@ void VCLSession::disposing() {
     for (auto const & i: list) {
         try {
             i.m_xListener->disposing(src);
+            SAL_INFO("vcl.se.debug", "  call Listener disposing");
         } catch (css::uno::RuntimeException & e) {
-            SAL_WARN("vcl.app", "ignoring RuntimeException " << e.Message);
+            SAL_WARN("vcl.se", "ignoring RuntimeException " << e.Message);
         }
     }
 }
@@ -349,17 +397,23 @@ void VCLSession::disposing() {
 
 OUString SAL_CALL vcl_session_getImplementationName()
 {
+    SAL_INFO("vcl.se", "vcl_session_getImplementationName");
+
     return OUString( "com.sun.star.frame.VCLSessionManagerClient" );
 }
 
 Sequence< OUString > SAL_CALL vcl_session_getSupportedServiceNames()
 {
+    SAL_INFO("vcl.se", "vcl_session_getSupportedServiceNames");
+
     Sequence< OUString > aRet { "com.sun.star.frame.SessionManagerClient" };
     return aRet;
 }
 
 css::uno::Reference< XInterface > SAL_CALL vcl_session_createInstance( SAL_UNUSED_PARAMETER const css::uno::Reference< XMultiServiceFactory > & )
 {
+    SAL_INFO("vcl.se", "vcl_session_createInstance");
+
     return static_cast< cppu::OWeakObject * >(new VCLSession);
 }
 
diff --git a/vcl/unx/generic/app/sm.cxx b/vcl/unx/generic/app/sm.cxx
index 5dea963552d3..fe88a8e56904 100644
--- a/vcl/unx/generic/app/sm.cxx
+++ b/vcl/unx/generic/app/sm.cxx
@@ -66,6 +66,8 @@ private:
 
 SalSession* X11SalInstance::CreateSalSession()
 {
+    SAL_INFO("vcl.sm", "X11SalInstance::CreateSalSession");
+
     SalSession * p = new IceSalSession;
     SessionManagerClient::open(p);
     return p;
@@ -73,8 +75,11 @@ SalSession* X11SalInstance::CreateSalSession()
 
 void IceSalSession::queryInteraction()
 {
+    SAL_INFO("vcl.sm", "IceSalSession::queryInteraction");
+
     if( ! SessionManagerClient::queryInteraction() )
     {
+        SAL_INFO("vcl.sm.debug", "  call SalSessionInteractionEvent");
         SalSessionInteractionEvent aEvent( false );
         CallCallback( &aEvent );
     }
@@ -82,16 +87,22 @@ void IceSalSession::queryInteraction()
 
 void IceSalSession::interactionDone()
 {
+    SAL_INFO("vcl.sm", "IceSalSession::interactionDone");
+
     SessionManagerClient::interactionDone( false );
 }
 
 void IceSalSession::saveDone()
 {
+    SAL_INFO("vcl.sm", "IceSalSession::saveDone");
+
     SessionManagerClient::saveDone();
 }
 
 bool IceSalSession::cancelShutdown()
 {
+    SAL_INFO("vcl.sm", "IceSalSession::cancelShutdown");
+
     SessionManagerClient::interactionDone( true );
     return false;
 }
@@ -129,6 +140,8 @@ public:
         , m_origIOErrorHandler(nullptr)
         , m_origErrorHandler(nullptr)
     {
+        SAL_INFO("vcl.sm", "ICEConnectionObserver::ICEConnectionObserver");
+
         m_nWakeupFiles[0] = m_nWakeupFiles[1] = 0;
     }
 
@@ -164,6 +177,8 @@ static unsigned char   *pSmRestartHint = nullptr;
 
 static void BuildSmPropertyList()
 {
+    SAL_INFO("vcl.sm", "BuildSmPropertyList");
+
     if( ! pSmProps )
     {
         OString aExec(OUStringToOString(SessionManagerClient::getExecName(), osl_getThreadTextEncoding()));
@@ -234,18 +249,24 @@ static void BuildSmPropertyList()
 
 bool SessionManagerClient::checkDocumentsSaved()
 {
+    SAL_INFO("vcl.sm", "SessionManagerClient::checkDocumentsSaved");
+
+    SAL_INFO("vcl.sm.debug", "  m_bcheckDocumentsSaved = " << (m_bDocSaveDone ? "true" : "false" ));
     return m_bDocSaveDone;
 }
 
 IMPL_STATIC_LINK( SessionManagerClient, SaveYourselfHdl, void*, pStateVal, void )
 {
+    SAL_INFO("vcl.sm", "SessionManagerClient, SaveYourselfHdl");
+
     // Decode argument smuggled in as void*:
     sal_uIntPtr nStateVal = reinterpret_cast< sal_uIntPtr >(pStateVal);
     bool shutdown = nStateVal != 0;
 
-    SAL_INFO("vcl.sm", "posting save documents event shutdown = " << (shutdown ? "true" : "false" ));
-
     static bool bFirstShutdown=true;
+
+    SAL_INFO("vcl.sm.debug", "  shutdown  = " << (shutdown ? "true" : "false" ) <<
+                             ", bFirstShutdown = " << (bFirstShutdown ? "true" : "false" ));
     if (shutdown && bFirstShutdown) //first shutdown request
     {
         bFirstShutdown = false;
@@ -264,6 +285,7 @@ IMPL_STATIC_LINK( SessionManagerClient, SaveYourselfHdl, void*, pStateVal, void
             if (pWindow && pWindow->IsVisible())
             {
                 *pSmRestartHint = SmRestartIfRunning;
+                SAL_INFO("vcl.sm.debug", "  pSmRestartHint = SmRestartIfRunning");
                 break;
             }
         }
@@ -280,7 +302,8 @@ IMPL_STATIC_LINK( SessionManagerClient, SaveYourselfHdl, void*, pStateVal, void
 
 IMPL_STATIC_LINK_NOARG( SessionManagerClient, InteractionHdl, void*, void )
 {
-    SAL_INFO("vcl.sm", "interaction link");
+    SAL_INFO("vcl.sm", "SessionManagerClient, InteractionHdl");
+
     if( m_pSession )
     {
         SalSessionInteractionEvent aEvent( true );
@@ -290,7 +313,8 @@ IMPL_STATIC_LINK_NOARG( SessionManagerClient, InteractionHdl, void*, void )
 
 IMPL_STATIC_LINK_NOARG( SessionManagerClient, ShutDownCancelHdl, void*, void )
 {
-    SAL_INFO("vcl.sm", "shutdown cancel");
+    SAL_INFO("vcl.sm", "SessionManagerClient, ShutDownCancelHdl");
+
     if( m_pSession )
     {
         SalSessionShutdownCancelEvent aEvent;
@@ -307,16 +331,14 @@ void SessionManagerClient::SaveYourselfProc(
     Bool
     )
 {
-    SAL_INFO("vcl.sm", "Session: save yourself, "
-        "save_type "
-            " local: " << (save_type == SmSaveLocal) <<
-            " global: " << (save_type == SmSaveGlobal) <<
-            " both: " << (save_type == SmSaveBoth) <<
-        " shutdown: " << shutdown <<
-        " interact_style: "
-            " SmInteractStyleNone: " << (interact_style == SmInteractStyleNone) <<
-            " SmInteractStyleErrors: " << (interact_style == SmInteractStyleErrors) <<
-            " SmInteractStyleErrors: " << (interact_style == SmInteractStyleAny));
+    SAL_INFO("vcl.sm", "SessionManagerClient::SaveYourselfProc");
+
+    SAL_INFO("vcl.sm.debug", "  save_type = "   << ((save_type == SmSaveLocal ) ? "local"  :
+                                                    (save_type == SmSaveGlobal) ? "global" : "both") <<
+                          ", shutdown = " <<        (shutdown ? "true" : "false" ) <<
+                          ", interact_style = " << ((interact_style == SmInteractStyleNone)   ? "SmInteractStyleNone"   :
+                                                    (interact_style == SmInteractStyleErrors) ? "SmInteractStyleErrors" :
+                                                                                                "SmInteractStyleAny"));
     BuildSmPropertyList();
     m_bDocSaveDone = false;
     /* #i49875# some session managers send a "die" message if the
@@ -333,11 +355,12 @@ void SessionManagerClient::SaveYourselfProc(
     // Smuggle argument in as void*:
     sal_uIntPtr nStateVal = shutdown;
     Application::PostUserEvent( LINK( nullptr, SessionManagerClient, SaveYourselfHdl ), reinterpret_cast< void * >(nStateVal) );
-    SAL_INFO("vcl.sm", "waiting for save yourself event to be processed" );
 }
 
 IMPL_STATIC_LINK_NOARG( SessionManagerClient, ShutDownHdl, void*, void )
 {
+    SAL_INFO("vcl.sm", "SessionManagerClient, ShutDownHdl");
+
     if( m_pSession )
     {
         SalSessionQuitEvent aEvent;
@@ -345,7 +368,8 @@ IMPL_STATIC_LINK_NOARG( SessionManagerClient, ShutDownHdl, void*, void )
     }
 
     const std::list< SalFrame* >& rFrames = vcl_sal::getSalDisplay(GetGenericData())->getFrames();
-    SAL_INFO("vcl.sm", (!rFrames.empty() ? "shutdown on first frame" : "shutdown event but no frame"));
+
+    SAL_INFO("vcl.sm.debug", "  rFrames.empty() = " << (rFrames.empty() ? "true" : "false"));
     if( !rFrames.empty() )
         rFrames.front()->CallCallback( SalEvent::Shutdown, nullptr );
 }
@@ -355,11 +379,12 @@ void SessionManagerClient::DieProc(
     SmPointer
     )
 {
-    SAL_INFO("vcl.sm", "Session: die");
+    SAL_INFO("vcl.sm", "SessionManagerClient::DieProc");
+
     if( connection == m_pSmcConnection )
     {
+        SAL_INFO("vcl.sm.debug", "  connection == m_pSmcConnection" );
         Application::PostUserEvent( LINK( nullptr, SessionManagerClient, ShutDownHdl ) );
-        SAL_INFO("vcl.sm", "waiting for shutdown event to be processed" );
     }
 }
 
@@ -368,14 +393,16 @@ void SessionManagerClient::SaveCompleteProc(
     SmPointer
     )
 {
-    SAL_INFO("vcl.sm", "Session: save complete");
+    SAL_INFO("vcl.sm", "SessionManagerClient::SaveCompleteProc");
 }
 
 void SessionManagerClient::ShutdownCanceledProc(
     SmcConn connection,
     SmPointer )
 {
-    SAL_INFO("vcl.sm", "Session: shutdown canceled" );
+    SAL_INFO("vcl.sm", "SessionManagerClient::ShutdownCanceledProc" );
+
+    SAL_INFO("vcl.sm.debug", "  connection == m_pSmcConnection = " <<  (( connection == m_pSmcConnection ) ? "true" : "false"));
     if( connection == m_pSmcConnection )
         Application::PostUserEvent( LINK( nullptr, SessionManagerClient, ShutDownCancelHdl ) );
 }
@@ -384,32 +411,39 @@ void SessionManagerClient::InteractProc(
                                         SmcConn connection,
                                         SmPointer )
 {
-    SAL_INFO("vcl.sm", "Session: interaction request completed" );
+    SAL_INFO("vcl.sm", "SessionManagerClient::InteractProc" );
+
+    SAL_INFO("vcl.sm.debug", "  connection == m_pSmcConnection = " <<  (( connection == m_pSmcConnection ) ? "true" : "false"));
     if( connection == m_pSmcConnection )
         Application::PostUserEvent( LINK( nullptr, SessionManagerClient, InteractionHdl ) );
 }
 
 void SessionManagerClient::saveDone()
 {
+    SAL_INFO("vcl.sm", "SessionManagerClient::saveDone");
+
     if( m_pSmcConnection )
     {
         assert(m_xICEConnectionObserver);
         osl::MutexGuard g(m_xICEConnectionObserver->m_ICEMutex);
         SmcSetProperties( m_pSmcConnection, nSmProps, ppSmProps );
         SmcSaveYourselfDone( m_pSmcConnection, True );
-        SAL_INFO("vcl.sm", "sent SaveYourselfDone SmRestartHint of " << *pSmRestartHint );
+        SAL_INFO("vcl.sm.debug", "  sent SmRestartHint = " << (*pSmRestartHint) );
         m_bDocSaveDone = true;
     }
 }
 
 void SessionManagerClient::open(SalSession * pSession)
 {
+    SAL_INFO("vcl.sm", "SessionManagerClient::open");
+
     assert(!m_pSession && !m_xICEConnectionObserver && !m_pSmcConnection);
         // must only be called once
     m_pSession = pSession;
     // This is the way Xt does it, so we can too:
     if( getenv( "SESSION_MANAGER" ) )
     {
+        SAL_INFO("vcl.sm.debug", "  getenv( SESSION_MANAGER ) = true");
         m_xICEConnectionObserver.reset(new ICEConnectionObserver);
         m_xICEConnectionObserver->activate();
 
@@ -442,9 +476,9 @@ void SessionManagerClient::open(SalSession * pSession)
                                                   sizeof( aErrBuf ),
                                                   aErrBuf );
             if( !m_pSmcConnection )
-                SAL_INFO("vcl.sm", "SmcOpenConnection failed: " << aErrBuf);
+                SAL_INFO("vcl.sm.debug", "  SmcOpenConnection failed: " << aErrBuf);
             else
-                SAL_INFO("vcl.sm", "SmcOpenConnection succeeded, client ID is " << pClientID );
+                SAL_INFO("vcl.sm.debug", "  SmcOpenConnection succeeded, client ID is " << pClientID );
             m_aClientID = OString(pClientID);
             free( pClientID );
             pClientID = nullptr;
@@ -453,6 +487,7 @@ void SessionManagerClient::open(SalSession * pSession)
         SalDisplay* pDisp = vcl_sal::getSalDisplay(GetGenericData());
         if( pDisp->GetDrawable(pDisp->GetDefaultXScreen()) && !m_aClientID.isEmpty() )
         {
+            SAL_INFO("vcl.sm.debug", "  SmcOpenConnection open: pDisp->GetDrawable = true");
             XChangeProperty( pDisp->GetDisplay(),
                              pDisp->GetDrawable( pDisp->GetDefaultXScreen() ),
                              XInternAtom( pDisp->GetDisplay(), "SM_CLIENT_ID", False ),
@@ -466,25 +501,30 @@ void SessionManagerClient::open(SalSession * pSession)
     }
     else
     {
-        SAL_INFO("vcl.sm", "no SESSION_MANAGER");
+        SAL_INFO("vcl.sm.debug", "  getenv( SESSION_MANAGER ) = false");
     }
 }
 
 const OString& SessionManagerClient::getSessionID()
 {
+    SAL_INFO("vcl.sm", "SessionManagerClient::getSessionID");
+
+    SAL_INFO("vcl.sm.debug", "  SessionID = " << m_aClientID);
     return m_aClientID;
 }
 
 void SessionManagerClient::close()
 {
+    SAL_INFO("vcl.sm", "SessionManagerClient::close");
+
     if( m_pSmcConnection )
     {
+        SAL_INFO("vcl.sm.debug", "  attempting SmcCloseConnection");
         assert(m_xICEConnectionObserver);
         {
             osl::MutexGuard g(m_xICEConnectionObserver->m_ICEMutex);
-            SAL_INFO("vcl.sm", "attempting SmcCloseConnection");
             SmcCloseConnection( m_pSmcConnection, 0, nullptr );
-            SAL_INFO("vcl.sm", "SmcConnection closed");
+            SAL_INFO("vcl.sm", "  SmcCloseConnection closed");
         }
         m_xICEConnectionObserver->deactivate();
         m_xICEConnectionObserver.reset();
@@ -494,11 +534,14 @@ void SessionManagerClient::close()
 
 bool SessionManagerClient::queryInteraction()
 {
+    SAL_INFO("vcl.sm", "SessionManagerClient::queryInteraction");
+
     bool bRet = false;
     if( m_pSmcConnection )
     {
         assert(m_xICEConnectionObserver);
         osl::MutexGuard g(m_xICEConnectionObserver->m_ICEMutex);
+        SAL_INFO("vcl.sm.debug", "  SmcInteractRequest" );
         if( SmcInteractRequest( m_pSmcConnection, SmDialogNormal, InteractProc, nullptr ) )
             bRet = true;
     }
@@ -507,27 +550,36 @@ bool SessionManagerClient::queryInteraction()
 
 void SessionManagerClient::interactionDone( bool bCancelShutdown )
 {
+    SAL_INFO("vcl.sm", "SessionManagerClient::interactionDone");
+
     if( m_pSmcConnection )
     {
         assert(m_xICEConnectionObserver);
         osl::MutexGuard g(m_xICEConnectionObserver->m_ICEMutex);
+        SAL_INFO("vcl.sm.debug", "  SmcInteractDone = " << (bCancelShutdown ? "true" : "false") );
         SmcInteractDone( m_pSmcConnection, bCancelShutdown ? True : False );
     }
 }
 
 OUString SessionManagerClient::getExecName()
 {
+    SAL_INFO("vcl.sm", "SessionManagerClient::getExecName");
+
     OUString aExec, aSysExec;
     osl_getExecutableFile( &aExec.pData );
     osl_getSystemPathFromFileURL( aExec.pData, &aSysExec.pData );
 
     if( aSysExec.endsWith(".bin") )
         aSysExec = aSysExec.copy( 0, aSysExec.getLength() - RTL_CONSTASCII_LENGTH(".bin") );
+
+    SAL_INFO("vcl.sm.debug", "  aSysExec = " << aSysExec);
     return aSysExec;
 }
 
 OString SessionManagerClient::getPreviousSessionID()
 {
+    SAL_INFO("vcl.sm", "SessionManagerClient::getPreviousSessionID");
+
     OString aPrevId;
 
     sal_uInt32 n = rtl_getAppCommandArgCount();
@@ -544,12 +596,14 @@ OString SessionManagerClient::getPreviousSessionID()
         }
     }
 
-    SAL_INFO("vcl.sm", "previous ID = " << aPrevId.getStr());
+    SAL_INFO("vcl.sm.debug", "  previous ID = " << aPrevId.getStr());
     return aPrevId;
 }
 
 void ICEConnectionObserver::activate()
 {
+    SAL_INFO("vcl.sm", "ICEConnectionObserver::activate");
+
     /*
      * Default handlers call exit, we don't care that strongly if something
      * happens to fail
@@ -561,6 +615,8 @@ void ICEConnectionObserver::activate()
 
 void ICEConnectionObserver::deactivate()
 {
+    SAL_INFO("vcl.sm", "ICEConnectionObserver::deactivate");
+
     oslThread t;
     {
         osl::MutexGuard g(m_ICEMutex);
@@ -573,18 +629,23 @@ void ICEConnectionObserver::deactivate()
     }
     if (t)
     {
+        SAL_INFO("vcl.sm.debug", "  terminate");
         terminate(t);
     }
 }
 
 void ICEConnectionObserver::wakeup()
 {
+    SAL_INFO("vcl.sm", "ICEConnectionObserver::wakeup");
+
     char cChar = 'w';
     OSL_VERIFY(write(m_nWakeupFiles[1], &cChar, 1) == 1);
 }
 
 void ICEConnectionObserver::terminate(oslThread iceThread)
 {
+    SAL_INFO("vcl.sm", "ICEConnectionObserver::terminate");
+
     osl_terminateThread(iceThread);
     wakeup();
     osl_joinWithThread(iceThread);
@@ -595,6 +656,8 @@ void ICEConnectionObserver::terminate(oslThread iceThread)
 
 void ICEConnectionWorker(void * data)
 {
+    SAL_INFO("vcl.sm", "ICEConnectionWorker");
+
     osl::Thread::setName("ICEConnectionWorker");
     ICEConnectionObserver * pThis = static_cast< ICEConnectionObserver * >(
         data);
@@ -637,7 +700,7 @@ void ICEConnectionWorker(void * data)
             char buf[4];
             while( read( pThis->m_nWakeupFiles[0], buf, sizeof( buf ) ) > 0 )
                 ;
-            SAL_INFO("vcl.sm", "file handles active in wakeup: " << nRet);
+            SAL_INFO("vcl.sm.debug", "  file handles active in wakeup: " << nRet);
             if( nRet == 1 )
                 continue;
         }
@@ -649,7 +712,7 @@ void ICEConnectionWorker(void * data)
             nRet = poll( pThis->m_pFilehandles+1, pThis->m_nConnections, 0 );
             if( nRet > 0 )
             {
-                SAL_INFO("vcl.sm", "IceProcessMessages");
+                SAL_INFO("vcl.sm.debug", "  IceProcessMessages");
                 Bool bReply;
                 for( int i = 0; i < pThis->m_nConnections; i++ )
                     if( pThis->m_pFilehandles[i+1].revents & POLLIN )
@@ -657,13 +720,16 @@ void ICEConnectionWorker(void * data)
             }
         }
     }
-    SAL_INFO("vcl.sm", "shutting down ICE dispatch thread");
+
+    SAL_INFO("vcl.sm.debug", "  shutting down ICE dispatch thread");
 }
 
 void ICEWatchProc(
     IceConn ice_conn, IcePointer client_data, Bool opening,
     SAL_UNUSED_PARAMETER IcePointer *)
 {
+    SAL_INFO("vcl.sm", "ICEWatchProc");
+
     // Note: This is a callback function for ICE; this implicitly means that a
     // call into ICE lib is calling this, so the m_ICEMutex MUST already be
     // locked by the caller.
@@ -671,6 +737,7 @@ void ICEWatchProc(
         client_data);
     if( opening )
     {
+        SAL_INFO("vcl.sm.debug", "  opening");
         int fd = IceConnectionNumber( ice_conn );
         pThis->m_nConnections++;
         pThis->m_pConnections = static_cast<IceConn*>(rtl_reallocateMemory( pThis->m_pConnections, sizeof( IceConn )*pThis->m_nConnections ));
@@ -680,6 +747,7 @@ void ICEWatchProc(
         pThis->m_pFilehandles[ pThis->m_nConnections ].events = POLLIN;
         if( pThis->m_nConnections == 1 )
         {
+            SAL_INFO("vcl.sm.debug", "  First connection");
             if (!pipe(pThis->m_nWakeupFiles))
             {
                 int flags;
@@ -714,6 +782,7 @@ void ICEWatchProc(
     }
     else // closing
     {
+        SAL_INFO("vcl.sm.debug", "  closing");
         for( int i = 0; i < pThis->m_nConnections; i++ )
         {
             if( pThis->m_pConnections[i] == ice_conn )
@@ -731,7 +800,7 @@ void ICEWatchProc(
         }
         if( pThis->m_nConnections == 0 && pThis->m_ICEThread )
         {
-            SAL_INFO("vcl.sm", "terminating ICEThread");
+            SAL_INFO("vcl.sm.debug", "  terminating ICEThread");
             oslThread t = pThis->m_ICEThread;
             pThis->m_ICEThread = nullptr;
 
@@ -745,8 +814,9 @@ void ICEWatchProc(
             pThis->m_ICEMutex.acquire();
         }
     }
-    SAL_INFO( "vcl.sm", "ICE connection on " << IceConnectionNumber( ice_conn ) << " " << (opening ? "inserted" : "removed"));
-    SAL_INFO( "vcl.sm", "Display connection is " << ConnectionNumber( vcl_sal::getSalDisplay(GetGenericData())->GetDisplay() ) );
+
+    SAL_INFO( "vcl.sm.debug", "  ICE connection     on " << IceConnectionNumber( ice_conn ) );
+    SAL_INFO( "vcl.sm.debug", "  Display connection is " << ConnectionNumber( vcl_sal::getSalDisplay(GetGenericData())->GetDisplay() ) );
 }
 
 /* vim:set shiftwidth=4 softtabstop=4 expandtab: */