Windows : Opening .gpx files when QMS already runs often fails

Issue #402 closed
Michel Durand created an issue

When QMS is not running, double-clicking a .gpx file leads to QMS starting and file opening : no problem.

But when QMS already runs : this is where I have trouble : I have to "insist" to open additional files : it works more or less 1 every 4 times

It was working fine with <v1.12 (VS 2017 problem maybe ?)

v1.12

Comments (12)

  1. kiozen

    As this seems to be a Windows related issue Windows community has to investigate and fix it. The class to look at is CSingleInstanceProxy.

    In short: The first instance of QMS opens a socket. A second instance probes for that socket. If it is found it will send all filenames attached to the application start-up command via the socket to the first instance. It will wait for a confirmation and close itself afterwards. You have to debug why this is not working reliably on Windows.

  2. wthaemelt

    Here are my observations on Windows10:

    • Modification of CSingleInstanceProxy.cpp: 2 additional debug output lines added immediately after if(serverName != "QMapShack"){...}.
    • Start first QMS instance with additional debug output (label: WT) with debug log. Debug log should have and has lines

      (WT) 2018-10-29 13:40:26.021 [debug] Socket check
      (WT) 2018-10-29 13:40:26.021 [debug] Info: "QMapShack-k-wth"  <==== from line: qDebug() << "Info:" << serverName;
      2018-10-29 13:40:26.021 [debug] CSingleInstanceProxy: Single instance server socket listening to "\\\\.\\pipe\\QMapShack-k-wth"
      
    • Double-click GPX-file to load file into QMS:

      • There should be the first 2 additional debug output lines shown above from CSingleInstanceProxy::CSingleInstanceProxy(const QStringList filenames) - none of them in the debug log!
      • Consequently, no other debug output from CSingleInstanceProxy.cpp.
    • Close QMS and start again first QMS instance with additional debug output with debug log. Debug file output as shown above.

    • Start second QMS instance with debug log (no double-click on GPX-file, direct start): Second instance doesn't start as expected, but debug file doesn't show new output from CSingleInstanceProxy.

    • Close QMS. Last (expected) line in debug log:

      2018-10-29 13:58:48.918 [debug] CSingleInstanceProxy::~CSingleInstanceProxy()

    Questions:

    • Can 2 different process instances write into 1 logfile? If not, this could explain the missing debug messages (and, maybe, other missing info in the debug file from the start of the second instance).
    • How to catch the debug output of the second QMS instance if one instance is already running?

    How to continue debugging?

  3. wthaemelt

    Continuation.

    • Start first QMS instance without debug log.
    • Start second instance of QMS with debug log from command line ===> debug log written for second instance (question: could debug log write mode be improved so that both instances can write to log?). Interesting lines:

      2018-10-30 6:48:50.244 [debug] Socket check
      2018-10-30 6:48:50.244 [debug] Info: "QMapShack-k-wth"
      2018-10-30 6:48:50.244 [debug] Sent parameters to primary instance. Result true
      2018-10-30 6:48:50.244 [debug] There can only be one. Exit.
      
    • Start second instance of QMS with debug log from command line:

         qmapshack.exe -f my.gpx
      
    • Result in debug file:

      2018-10-30 6:54:37.178 [debug] Socket check
      2018-10-30 6:54:37.178 [debug] Info: "QMapShack-k-wth"
      2018-10-30 6:54:37.178 [debug] Sent parameters to primary instance. Result false <=================== !
      2018-10-30 6:54:37.178 [debug] There can only be one. Exit.
      

    My interpretation: communication between both QMS instances fails and therefore no new project in first instance.

  4. kiozen

    Currently there can be only one instance that writes to log. Windows is a bit peculiar in writing output to the console which would make life much easier.

    Anyway, the "sent parameters..." is kind of ok. I would suggest to add a bit more debug output. In line 44

            QDataStream stream(&socket);
            stream << filenames;
            socket.waitForBytesWritten(3000);
    

    you want to output filenames. That part will be invoked on the 2nd instance.

    On the 1st instance you want to add debug output to 86

            QStringList filenames;
            QDataStream stream(socket);
            stream >> filenames;
    

    To see what it receives. And you can place a breakpoint at line 89

    w.loadGISData(filenames);
    

    to follow step by step if the data is loaded.

  5. kiozen

    Maybe the timeout of 3000ms is too short. You can try to increase ot by search and replace (Yes, I should have defined it as a constant)

  6. wthaemelt
    • Increase of time-out from 3000 to 6000 insocket.waitForBytesWritten and socket.waitForReadyRead doesn't make a difference.
    • Debug log of second instance:

      2018-10-30 9:50:50.801 [debug] Socket check
      2018-10-30 9:50:50.801 [debug] Info: "QMapShack-k-wth"
      2018-10-30 9:50:50.801 [debug] Socket check1  <======== before call to socket.waitForBytesWritten
      2018-10-30 9:50:50.801 [debug] ("d:\\Scripts\\my.gpx") <=== qDebug() << filenames;
      2018-10-30 9:50:50.801 [debug] Socket check2  <======== after call to socket.waitForBytesWritten and before call to socket.waitForReadyRead
      2018-10-30 9:50:50.802 [debug] Sent parameters to primary instance. Result false <=== after call to socket.waitForReadyRead
      2018-10-30 9:50:50.802 [debug] There can only be one. Exit.
      
    • Conclusion from the debug log timestamps: no visible delay. If 3000 means 3000 ms = 3 sec. waiting should be visible in the timestamps (?).

    • Next start first instance with debug log and second one without debug log having qDebug() << filenames; added after stream >> filenames; in slotNewConnection.

    • Debug log output:

      2018-10-30 10:15:32.597 [debug] () <=========== no filename(s) and thus nothing added to workspace!
      
    • Similar to second instance no visible delay from wait... in timestamps.

    • Having the executed the previous debug step there follows stream << true; in the first instance. But the second instance gets a false (see log of second instance above).
    • My conclusion: sockets don't work as expected.
  7. wthaemelt
    • Running second instance with debug log:

    Code:

        qDebug() << "Socket check";
        qDebug() << "Info:" << serverName;
    
        QLocalSocket socket;
        socket.connectToServer(serverName);
    
        qDebug() << socket.error();
        qDebug() << socket.errorString() ;
        qDebug() << socket.state();
    

    Debug log:

        2018-10-30 13:08:18.609 [debug] Socket check
        2018-10-30 13:08:18.609 [debug] Info: "QMapShack-k-wth"
        2018-10-30 13:08:18.609 [debug] QLocalSocket::UnknownSocketError  <==================!
        2018-10-30 13:08:18.609 [debug] "Unbekannter Fehler"
        2018-10-30 13:08:18.609 [debug] QLocalSocket::ConnectedState
    

    The UnknownSocketError remains there after each socket command.

    • Running first instance with debug log:

    Code:

        QLocalSocket * socket = server->nextPendingConnection();
        qDebug() << "New connection";
    
        qDebug() << socket->error();
        qDebug() << socket->errorString() ;
        qDebug() << socket->state();
        qDebug() << socket->isWritable();
    

    Debug log:

        2018-10-30 13:17:08.182 [debug] New connection
        2018-10-30 13:17:08.182 [debug] QLocalSocket::UnknownSocketError   <==================!
        2018-10-30 13:17:08.182 [debug] "Unbekannter Fehler"
        2018-10-30 13:17:08.182 [debug] QLocalSocket::ConnectedState
        2018-10-30 13:17:08.182 [debug] true
    

    The UnknownSocketError remains there after each socket command.

    I found a single link in the Internet which might be related to the given issue:

    https://stackoverflow.com/questions/18945407/is-qlocalsocket-really-used-for-namedpipes

    But the language used in the article is some kind of Chinese for me.

  8. wthaemelt

    While testing more I now came across the case described already by Michel: I can double-click a GPX file or open a second QMS instance from the command line with GPX file parameter and the GPX file opens in the workspace. What I did inbetween: I had a look at the named pipes for QMS with ProcessExplorer and tried to connect/write to the named pipe from a Python script (without success). Even after a restart of the Windows system the double-click is still working!

    Could the firewall be involved? I had an update of my definition files before I succeeded with the double-click! And here is one more link to a similar issue:

    https://superuser.com/questions/462443/what-are-reasons-for-local-windows-named-pipes-to-fail

    (sockets in Windows are implemented as named pipes!)

  9. wthaemelt

    Just some additional information/comments:

    • All double-click tests in the last 24h 100% without problems on my notebook.
    • Debug log still shows QLocalSocket::UnknownSocketError.
    • My final comment: on a Windows system QMS sockets may not work as expected due to a unclear Windows problem.
    • Easy replacement for double-click: Drag&drop file on workspace.
  10. Log in to comment