TimestamperFailed

[hainguyen291]

Hi everybody,

I created my own service on my client server.

However, when I tested service from client, I got this error: LoggingFailed.TimestamperFailed. The picture below is my SS's state.

Do you think the error appeared due to not configuring timestamp request yet?

Regards, Hai.

[petkivim]

Hi @hainguyen291,

Have you checked out /var/log/xroad/proxy.log and /var/log/xroad/signer.log log files for more detailed information about the problem?

Regards, Petteri

[hainguyen291]

Hi @petkivim

I could find signer.log but proxy.log

hai@hai:/var/log/xroad$ locate proxy.log /home/hai/xroad_source_code/X-Road/src/packages/xroad/debian/xroad-proxy.logrotate hai@hai:/var/log/xroad$ locate signer.log /var/log/upstart/xroad-signer.log.1.gz /var/log/upstart/xroad-signer.log.2.gz /var/log/upstart/xroad-signer.log.3.gz /var/log/upstart/xroad-signer.log.4.gz /var/log/xroad/signer.log hai@hai:/var/log/xroad$

Here is the log of signer.log:

==> signer.log <== 2018-05-11 10:14:27,987 INFO [main] ee.ria.xroad.common.util.AdminPort - Started AdminPort on port 5559 2018-05-11 10:14:27,989 INFO [main] org.eclipse.jetty.server.Server - jetty-9.4.z-SNAPSHOT 2018-05-11 10:14:28,004 INFO [main] o.e.jetty.server.AbstractConnector - Started AdminPort@5b6ec132{HTTP/1.1,[http/1.1]}{127.0.0.1:5559} 2018-05-11 10:14:28,004 INFO [main] org.eclipse.jetty.server.Server - Started @13268ms 2018-05-11 10:14:32,761 INFO [Signer-akka.actor.default-dispatcher-3] ee.ria.xroad.signer.OcspRetrievalJob - OCSP-retrieval configured to be inactive, job auto-scheduling disabled 2018-05-11 10:14:32,762 INFO [Signer-akka.actor.default-dispatcher-3] ee.ria.xroad.signer.OcspRetrievalJob - OCSP-retrieval configured to be inactive, job auto-scheduling disabled 2018-05-11 10:15:03,734 ERROR [Signer-akka.actor.default-dispatcher-14] e.r.x.s.t.token.AbstractToken - TokenNotActive: Token 'softToken' not active 2018-05-11 10:16:02,019 ERROR [Signer-akka.actor.default-dispatcher-4] e.r.x.s.t.token.AbstractToken - TokenNotActive: Token 'softToken' not active 2018-05-11 10:17:01,201 ERROR [Signer-akka.actor.default-dispatcher-17] e.r.x.s.t.token.AbstractToken - TokenNotActive: Token 'softToken' not active 2018-05-11 10:18:01,404 ERROR [Signer-akka.actor.default-dispatcher-17] e.r.x.s.t.token.AbstractToken - TokenNotActive: Token 'softToken' not active

Regards, Hai

[hainguyen291]

The strange thing was, everything becomes "normal" when I restore SS at the state that it worked. So, I can use services via SS again. However, after a day passed by, the issue above returned without any changes to SS.

[petkivim]

@hainguyen291 Have you activated the soft token by entering the PIN code on the security server UI? The error below indicates that the PIN code has not been entered.

2018-05-11 10:18:01,404 ERROR [Signer-akka.actor.default-dispatcher-17] e.r.x.s.t.token.AbstractToken - TokenNotActive: Token 'softToken' not active

[hainguyen291]

@petkivim It is the error on 05/11. I entered PIN on SS after that. I find out this which related to Network Time Protocol (NTP). My timestamp service will be expired after every 4 hours. It seems that I need to setup my own NTP to support SS, don't I?

[hainguyen291]

@petkivim Here is the log of proxy.log file:

2018-05-17 13:27:18,127 [Proxy-akka.actor.default-dispatcher-3] INFO e.r.xroad.proxy.messagelog.TaskQueue - Start time-stamping 59 message records 2018-05-17 13:27:18,145 [Proxy-akka.actor.default-dispatcher-3] ERROR e.r.x.p.m.AbstractTimestampRequest - Failed to get time stamp from http://10.145.13.126:8899 java.lang.RuntimeException: Received HTTP error: 502 - Bad Gateway at ee.ria.xroad.proxy.messagelog.TimestamperUtil.makeTsRequest(TimestamperUtil.java:87) ~[messagelog-1.0.jar:na] at ee.ria.xroad.proxy.messagelog.AbstractTimestampRequest.makeTsRequest(AbstractTimestampRequest.java:91) [messagelog-1.0.jar:na] at ee.ria.xroad.proxy.messagelog.AbstractTimestampRequest.execute(AbstractTimestampRequest.java:62) [messagelog-1.0.jar:na] at ee.ria.xroad.proxy.messagelog.TimestamperWorker.handleTimestampTask(TimestamperWorker.java:92) [messagelog-1.0.jar:na] at ee.ria.xroad.proxy.messagelog.TimestamperWorker.onReceive(TimestamperWorker.java:49) [messagelog-1.0.jar:na] at akka.actor.UntypedActor$$anonfun$receive$1.applyOrElse(UntypedActor.scala:165) [proxy-1.0.jar:na] at akka.actor.Actor$class.aroundReceive(Actor.scala:484) [proxy-1.0.jar:na] at akka.actor.UntypedActor.aroundReceive(UntypedActor.scala:95) [proxy-1.0.jar:na] at akka.actor.ActorCell.receiveMessage(ActorCell.scala:526) [proxy-1.0.jar:na] at akka.actor.ActorCell.invoke(ActorCell.scala:495) [proxy-1.0.jar:na] at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:257) [proxy-1.0.jar:na] at akka.dispatch.Mailbox.run(Mailbox.scala:224) [proxy-1.0.jar:na] at akka.dispatch.Mailbox.exec(Mailbox.scala:234) [proxy-1.0.jar:na] at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260) [proxy-1.0.jar:na] at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339) [proxy-1.0.jar:na] at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979) [proxy-1.0.jar:na] at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107) [proxy-1.0.jar:na] 2018-05-17 13:27:18,145 [Proxy-akka.actor.default-dispatcher-3] ERROR e.r.x.p.messagelog.TimestamperWorker - Timestamper failed for message records [1, 2, 3, 4, 5, 29, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 30, 31, 32, 33, 34, 35, 36, 37, 38,

It seems that my TSA service from http://10.145.13.126:8899 doesn't work correctly. (I used test-CA server to create ocsp and tsa services)

[petkivim]

You don't need to setup your own NTP, because the problem is not related to NTP at all. The reason why your security server works 4 hours is that acceptable-timestamp-failure-period property of the message-log add-on is configured to 14000 seconds which is 4 hours. Below there's the description of the property:

Defines the time period (in seconds) for how long is time-stamping allowed to fail (for whatever reasons) before the message log stops accepting any more messages (and consequently the security server stops accepting requests). Set to 0 to disable this check. The value of this parameter should not be lower than the value of the central server system parameter timeStampingIntervalSeconds.

The root cause of the problem is that there's something wrong with your TSA service. Have you tried to restart the service?

sudo /sbin/start tsa

[hainguyen291]

@petkivim Yeah, I also thought my TSA service didn't work correctly. I restarted TSA several times but it didn't work. I had to restore configuration backup of SS to make it worked again. However, it also worked in 4 hours only.

[hainguyen291]

This is the log of proxy.log once SS could work.

2018-05-18 09:49:32,303 [Proxy-akka.actor.default-dispatcher-2] ERROR e.r.x.p.messagelog.TimestamperWorker - Timestamper failed for message records [1, 2, 3, 4, 5, 29, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 30, 31, 32, 33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 55, 44, 45, 46, 47, 48, 49, 50, 51, 52, 53, 54, 56, 57, 58, 59, 60, 61, 62, 63, 64, 65, 66, 67, 68, 69, 70, 71, 72, 73, 74, 75, 76, 77, 78, 79, 80, 81, 82]: Failed to get time stamp from any time-stamping providers 2018-05-18 09:49:35,833 [qtp1970612644-3045] INFO ee.ria.xroad.common.util.AdminPort - Admin request: /timestampstatus 2018-05-18 09:49:35,833 [qtp1970612644-3045] INFO ee.ria.xroad.proxy.ProxyMain - /timestampstatus 2018-05-18 09:49:35,833 [qtp1970612644-3045] INFO ee.ria.xroad.proxy.ProxyMain - Checking timestamp server status for url http://10.145.13.126:8899 2018-05-18 09:49:35,838 [qtp1970612644-3045] INFO ee.ria.xroad.proxy.ProxyMain - Checking timestamp server con sun.net.www.protocol.http.HttpURLConnection:http://10.145.13.126:8899 2018-05-18 09:49:35,842 [qtp1970612644-3045] WARN ee.ria.xroad.proxy.ProxyMain - ## Timestamp check received HTTP error: 502 - Bad Gateway. Might still be ok 2018-05-18 09:49:35,843 [qtp1970612644-3045] INFO ee.ria.xroad.proxy.ProxyMain - result {http://10.145.13.126:8899=DiagnosticsStatus(returnCode=0, prevUpdate=09:49:35.842, nextUpdate=null, description=http://10.145.13.126:8899)} 2018-05-18 09:49:35,843 [qtp1970612644-3045] INFO ee.ria.xroad.proxy.ProxyMain - statusFromLogManager {}

[hainguyen291]

Hi @petkivim I thought I have fixed the TSA issue already.

SS Diagnostic

Thanks for your support! Hai