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>

1 files changed, 104 insertions, 34 deletions

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: */