virtuoso-opensource icon indicating copy to clipboard operation
virtuoso-opensource copied to clipboard
verified publisher icon openlink

Service failed to start, "protocol" error

Open srlin5 opened this issue 3 years ago • 8 comments 

● virtuoso.service - Virtuoso Open Source Edition 7.2
     Loaded: loaded (/etc/systemd/system/virtuoso.service; enabled; vendor preset: enabled)
     Active: failed (Result: protocol) since Mon 2022-08-29 13:28:34 CEST; 1min 21s ago
    Process: 3205068 ExecStart=/opt/bin/virtuoso-t -c /opt/var/lib/virtuoso/db/virtuoso.ini (code=exited, status=0/SUCCESS)
   Main PID: 3205068 (code=exited, status=0/SUCCESS)
      Tasks: 22 (limit: 76907)
     Memory: 13.0G
     CGroup: /system.slice/virtuoso.service
             └─3205069 /opt/bin/virtuoso-t -c /opt/var/lib/virtuoso/db/virtuoso.ini

Aug 29 13:28:34 sparql systemd[1]: Starting Virtuoso Open Source Edition 7.2...
**Aug 29 13:28:34 sparql systemd[1]: **virtuoso.service: Failed with result 'protocol'.**
Aug 29 13:28:34 sparql systemd[1]: Failed to start Virtuoso Open Source Edition 7.2.**

Log:

10:34:20 Checkpoint started
10:34:20 Checkpoint finished, log reused
11:18:10 * Monitor: Locks are held for a long time
11:18:41 /opt/bin/virtuoso-t() [0x8d712d]
11:18:41 /opt/bin/virtuoso-t() [0x8d71a8]
11:18:41 /opt/bin/virtuoso-t() [0x82e6eb]
11:18:41 /opt/bin/virtuoso-t() [0x834d32]
11:18:41 /opt/bin/virtuoso-t() [0x460237]
11:18:41 /opt/bin/virtuoso-t() [0x463602]
11:18:41 /opt/bin/virtuoso-t() [0x503341]
11:18:41 /opt/bin/virtuoso-t() [0x506dbe]
11:18:41 /opt/bin/virtuoso-t() [0x634d25]
11:18:41 /opt/bin/virtuoso-t() [0x5ccf19]
11:18:41 /opt/bin/virtuoso-t() [0x5c5ae1]
11:18:41 /opt/bin/virtuoso-t() [0x5c5d90]
11:18:41 /opt/bin/virtuoso-t() [0x5c5ae1]
11:18:41 /opt/bin/virtuoso-t() [0x5c5ae1]
11:18:41 /opt/bin/virtuoso-t() [0x5c5e9f]
11:18:41 /opt/bin/virtuoso-t() [0x5ccc50]
11:18:41 /opt/bin/virtuoso-t() [0x5c5ae1]
11:18:41 /opt/bin/virtuoso-t() [0x5c5e9f]
11:18:41 /opt/bin/virtuoso-t() [0x5cd06a]
11:18:41 /opt/bin/virtuoso-t() [0x5c5ae1]
11:18:41 /opt/bin/virtuoso-t() [0x5c5ae1]
11:18:41 /opt/bin/virtuoso-t() [0x5c5e9f]
11:18:41 /opt/bin/virtuoso-t() [0x5ccc50]
11:18:41 /opt/bin/virtuoso-t() [0x5c5ae1]
11:18:41 /opt/bin/virtuoso-t() [0x5c5ae1]
11:18:41 /opt/bin/virtuoso-t() [0x5c5e9f]
11:18:41 /opt/bin/virtuoso-t() [0x5ccc50]
11:18:41 /opt/bin/virtuoso-t() [0x5c5ae1]
11:18:41 /opt/bin/virtuoso-t() [0x5c5ae1]
11:18:41 /opt/bin/virtuoso-t() [0x5c5e9f]
11:18:41 /opt/bin/virtuoso-t() [0x5ccc50]
11:18:41 /opt/bin/virtuoso-t() [0x5c5ae1]
11:18:41 /opt/bin/virtuoso-t() [0x5c5ae1]
11:18:41 /opt/bin/virtuoso-t() [0x5c5e9f]
11:18:41 /opt/bin/virtuoso-t() [0x5ccaa9]
11:18:41 /opt/bin/virtuoso-t() [0x5c5ae1]
11:18:41 /opt/bin/virtuoso-t() [0x5c5ae1]
11:18:41 /opt/bin/virtuoso-t() [0x5c5e9f]
11:18:41 /opt/bin/virtuoso-t() [0x5ccaa9]
11:18:41 /opt/bin/virtuoso-t() [0x5c5ae1]
11:18:41 /opt/bin/virtuoso-t() [0x5c5ae1]
11:18:41 /opt/bin/virtuoso-t() [0x5c5e9f]
11:18:41 /opt/bin/virtuoso-t() [0x5ccaa9]
11:18:41 /opt/bin/virtuoso-t() [0x5c5ae1]
11:18:41 /opt/bin/virtuoso-t() [0x5c5ae1]
11:18:41 /opt/bin/virtuoso-t() [0x5c5e9f]
11:18:41 /opt/bin/virtuoso-t() [0x5ccaa9]
11:18:41 /opt/bin/virtuoso-t() [0x5c5ae1]
11:18:41 /opt/bin/virtuoso-t() [0x5c5d90]
11:18:41 /opt/bin/virtuoso-t() [0x516d51]
11:18:41 /opt/bin/virtuoso-t() [0x5170e1]
11:18:41 /opt/bin/virtuoso-t() [0x5c5ae1]
11:18:41 /opt/bin/virtuoso-t() [0x5c5d90]
11:18:41 /opt/bin/virtuoso-t() [0x5fd2e4]
11:18:41 /opt/bin/virtuoso-t() [0x5c5ae1]
11:18:41 /opt/bin/virtuoso-t() [0x5d045a]
11:18:41 /opt/bin/virtuoso-t() [0x53c170]
11:18:41 /opt/bin/virtuoso-t() [0x5968f8]
11:18:41 /opt/bin/virtuoso-t() [0x59edf7]
11:18:41 /opt/bin/virtuoso-t() [0x5c5be2]
11:18:41 /opt/bin/virtuoso-t() [0x5cee59]
11:18:41 /opt/bin/virtuoso-t() [0x596d95]
11:18:41 /opt/bin/virtuoso-t() [0x59f34f]
11:18:41 /opt/bin/virtuoso-t() [0x5c5be2]
11:18:41 /opt/bin/virtuoso-t() [0x5cee59]
11:18:41 /opt/bin/virtuoso-t() [0x596d95]
11:18:41 /opt/bin/virtuoso-t() [0x598068]
11:18:41 /opt/bin/virtuoso-t() [0x59c377]
11:18:41 /opt/bin/virtuoso-t() [0x5c5ac8]
11:18:41 /opt/bin/virtuoso-t() [0x5d045a]
11:18:41 /opt/bin/virtuoso-t() [0x5d17d5]
11:18:41 /opt/bin/virtuoso-t() [0x6d8b72]
11:18:41 /opt/bin/virtuoso-t() [0x4b1f68]
11:18:41 /opt/bin/virtuoso-t() [0x4b38ce]
11:18:41 /opt/bin/virtuoso-t() [0x4b3ab6]
11:18:41 /opt/bin/virtuoso-t() [0x4b3f1a]
11:18:41 /opt/bin/virtuoso-t() [0x8e1c53]
11:18:41 /lib/x86_64-linux-gnu/libpthread.so.0(+0x8609) [0x7f42900eb609]
11:18:41 /lib/x86_64-linux-gnu/libc.so.6(clone+0x43) [0x7f428febb163]
11:18:41 GPF: cetop.c:545 can't have a range that shifts from compatble to less dtp in next ce

===

Anybody know how to fix this and/or what it means? The webserver seems to be running though.

srlin5 avatar Aug 29 '22 12:08 srlin5

Can you show me the output of the following command:

$ /opt/bin/virtuoso-t -?

I also would like to know more about what operations you performed on the database prior to the restart?

Is this a newly created database, or an existing db?

Do you have a backup of the database?

pkleef avatar Aug 29 '22 13:08 pkleef

/opt/bin/virtuoso-t -?

No output on this command.

We didn't perform anything prior, it's an existing database and yes we have a backup.

srlin5 avatar Aug 29 '22 15:08 srlin5

Could it be the old version we're using:

Version: 07.20.3217
Build: Sep 7 2016

srlin5 avatar Aug 29 '22 16:08 srlin5

The log was showing some more errors later on:

17:21:46 INFO: { Loading plugin 1: Type `plain', file `wikiv' in `/opt2/lib/virtuoso/hosting'
17:21:46 ERROR:   FAILED  plugin 1: Unable to locate file }
17:21:46 INFO: { Loading plugin 2: Type `plain', file `mediawiki' in `/opt2/lib/virtuoso/hosting'
17:21:46 ERROR:   FAILED  plugin 2: Unable to locate file }
17:21:46 INFO: { Loading plugin 3: Type `plain', file `creolewiki' in `/opt2/lib/virtuoso/hosting'
17:21:46 ERROR:   FAILED  plugin 3: Unable to locate file }
17:21:46 INFO: OpenLink Virtuoso Universal Server
17:21:46 INFO: Version 07.20.3217-pthreads for Linux as of Sep  7 2016
17:21:46 INFO: uses parts of OpenSSL, PCRE, Html Tidy
17:21:53 INFO: Database version 3126
17:21:53 INFO: SQL Optimizer enabled (max 1000 layouts)
17:21:54 INFO: Compiler unit is timed at 0.000103 msec
17:22:00 INFO: Roll forward started
17:22:00 INFO:     3 transactions, 185 bytes replayed (100 %)
17:22:00 INFO: Roll forward complete
17:22:01 INFO: Checkpoint started
17:22:02 INFO: Checkpoint finished, log reused
17:22:02 ERROR: Failed HTTP listen at 8890.
17:22:02 INFO: Server exiting

Seems the hosting directory is missing as well.

srlin5 avatar Aug 29 '22 16:08 srlin5

  • That VERY old binary (and supporting binaries, etc.) could certainly be a contributing factor. An update is likely to be in your future.

  • @pkleef requested output of /opt/bin/virtuoso-t -? because it generally helps us to know the last commit made to the code from which your binary was built. This git_head is revealed in the parentheses at the end of the Version line in that command's output, when the correct path to the binary is used in the command.

    git_head is also available via a SPARQL query, when the instance is running, as described here.

    All that said -- the exact git_head of your binary is probably not needed, given that we know it was built more than 5 years (and hundreds of commits) ago.

  • The hosting directory is probably not a problem, as it is only needed when you're running particular add-ons and plug-ins. The errors about the missing —

    `wikiv' in `/opt2/lib/virtuoso/hosting'
`mediawiki' in `/opt2/lib/virtuoso/hosting'
`creolewiki' in `/opt2/lib/virtuoso/hosting'

    — are only a problem if you were trying to run one of those wiki apps.

  • @pkleef will be better able than I to advise on your next steps.

TallTed avatar Aug 29 '22 17:08 TallTed 

# /opt/bin/virtuoso-t -?
Virtuoso Open Source Edition (Column Store) (multi threaded)
Version 7.2.4.2.3217-pthreads as of Sep  7 2016
Compiled for Linux (x86_64-pc-linux-gnu)
Copyright (C) 1998-2016 OpenLink Software

srlin5 avatar Aug 30 '22 08:08 srlin5

First lets focus on the following message in the log file:

17:22:01 INFO: Checkpoint started
17:22:02 INFO: Checkpoint finished, log reused
17:22:02 ERROR: Failed HTTP listen at 8890.
17:22:02 INFO: Server exiting

This error occurs when another process already has this port 8890 open on the server. This could be another virtuoso instance, or a third party application.

Since you stated:

The webserver seems to be running though.

we can assume there is already a Virtuoso process running using the same port(s). This will prevent the systemd service from starting Virtuoso using the virtuoso.service file you created.

What is slightly worrying is the face that your messages have references to both /opt/ and /opt2/ directories which could indicate you moved your installation at some point in time, but did not modify all files accordingly.

There are two possibilities:

The first possibility is that someone started another Virtuoso instance in a separate set of directories on this server but using the same port numbers. In this case they should modify the virtuoso.ini file in that directory to change the ServerPort settings in both the [Parameters] and the [HTTPServer] sections to a different set of port numbers, restart that Virtuoso instance which should free ports 1111 and 8890 so they can be used by the instance in /opt/. Of course if this Virtuoso instance is not required, then you can just shut it down to free up the ports.

The second possibility is that someone removed the virtuoso.lck file from the database directory. This is more serious as that lock file contains the PID (Process ID) of the running Virtuoso instance. Virtuoso will normally not start up if there is an active virtuoso.lck file present in the database directory, as the virtuoso.db file cannot be shared between multiple processes. This could potentially lead to a broken database. In which case you ultimately would need to restore the database from a backup.

Suggested steps:

  1. Shutdown all Virtuoso instances on this machine.
  2. Build/Install the latest Virtuoso Open Source Edition in /opt
  3. Attempt to start your database with this latest binary.
  4. If your database has been corrupted, you need to restore it from your backup.

pkleef avatar Aug 30 '22 14:08 pkleef

@pkleef Thanks, we'll check all of the points.

srlin5 avatar Aug 31 '22 10:08 srlin5