History | Log In     View a printable version of the current page.  
Issue Details (XML | Word | Printable)

Key: QB-3083
Type: Bug Bug
Status: Resolved Resolved
Resolution: Fixed
Priority: Critical Critical
Assignee: Unassigned
Reporter: Piotr Jedrys
Votes: 0
Watchers: 1
Operations

If you were logged in you would be able to see more operations.
QuickBuild

Duplicate entries on DB, no measurements for nodes

Created: 20/Nov/17 02:47 PM   Updated: 24/Nov/17 11:52 AM
Component/s: None
Affects Version/s: 7.0.28
Fix Version/s: 7.0.29

Original Estimate: Unknown Remaining Estimate: Unknown Time Spent: Unknown
Environment: Linux 4.4.0-83-generic #106~14.04.1-Ubuntu SMP Mon Jun 26 18:10:19 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux


 Description  « Hide
After upgrade to QuickBuild 7.0.28 (from 6.0) we still see multiple errors on measurements data:

Query is: /* insert com.pmease.quickbuild.model.MeasurementDataR01 */ insert into QB_MEASUREMENT_DATAR01 (QB_METRIC_NAME, QB_SOURCE, QB_TIMESTAMP, QB_VALUE, QB_ID) values (?, ?, ?, ?, ?), parameters ['disk.usage./','node_x:8811',1511189148247,0.15542780752143154,647659]
2017-11-20 14:45:49,894 [pool-1-thread-51850] INFO com.pmease.quickbuild.DefaultBuildEngine - Processing build request (configuration:root/configuration_x, request id:f0de6076-8cf2-43b4-8b6a-e6ffdb94514f)
2017-11-20 14:45:49,905 [pool-1-thread-51850] INFO com.pmease.quickbuild.DefaultBuildEngine - Checking build condition on node (address: node_x:8811, ip: 10.123.25.180)...
2017-11-20 14:45:49,975 [pool-1-thread-51867] WARN org.hibernate.engine.jdbc.spi.SqlExceptionHelper - SQL Error: 1062, SQLState: 23000
2017-11-20 14:45:49,975 [pool-1-thread-51867] ERROR org.hibernate.engine.jdbc.spi.SqlExceptionHelper - Duplicate entry '1511189149955-node_x:8811-disk.usage./opt' for key 'PK_DATA_R01'

This problem makes the log unreadable, growing very fast

 All   Comments   Work Log   Change History      Sort Order:
Piotr Jedrys [21/Nov/17 02:01 PM]
After manually removing contraints from DB, I can see that most of the rows are pushed twice with the same value:

mysql> select * from QB_MEASUREMENT_DATAR03;
+-------+----------------------------------------------------+-------------------------------------+---------------+---------------------------+
| QB_ID | QB_METRIC_NAME | QB_SOURCE | QB_TIMESTAMP | QB_VALUE |
+-------+----------------------------------------------------+-------------------------------------+---------------+---------------------------+
| 103 | jvm.memoryUsage | quickbuild-agent-X:8811 | 1511272791582 | 0.06191427686063185 |
| 104 | disk.usage./opt/buildagent | quickbuild-agent-X:8811 | 1511272791583 | 0.6052124435108935 |
| 105 | disk.usage./opt/buildagent | quickbuild-agent-X:8811 | 1511272791583 | 0.6052124435108935 |
| 106 | disk.usage./opt/buildagent | quickbuild-agent-X:8811 | 1511272791583 | 0.6052124435108935 |
| 107 | cpu.totalUsage | quickbuild-agent-X:8811 | 1511272791583 | 0.0035431134379871783 |
| 108 | disk.usage./ | quickbuild-agent-X:8811 | 1511272791583 | 0.6052124435108935 |
| 109 | disk.frees./ | quickbuild-agent-X:8811 | 1511272791583 | 261964926976 |
| 110 | disk.frees./opt/buildagent | quickbuild-agent-X:8811 | 1511272791583 | 261964926976 |
| 111 | disk.frees./opt/buildagent | quickbuild-agent-X:8811 | 1511272791583 | 261964926976 |

Steve Luo [21/Nov/17 02:05 PM]
Is this specifically for one agent or for all agent?

Piotr Jedrys [21/Nov/17 02:15 PM]
for all agents and for master as well

Steve Luo [21/Nov/17 02:17 PM]
strange, how about to start a new QuickBuild instance to see if the issue still can be reproduced?

Piotr Jedrys [21/Nov/17 02:19 PM]
I already tried:
- restart it,
- clean tables, restore them, restart QB
- start a fresh instance with the same DB connected

Neither of those work

Steve Luo [21/Nov/17 02:22 PM]
How about use a fresh db?

Piotr Jedrys [21/Nov/17 02:28 PM]
We cannot do that - it is a production environment, and we need all of the data which is stored there already

Steve Luo [21/Nov/17 02:32 PM]
Yes, I know, what I want to confirm is that a fresh QuickBuild instance with fresh DB can work as expected in your environment. We can't reproduce this issue in our environment and also haven't received such report from our other customers'.

Piotr Jedrys [21/Nov/17 02:34 PM]
ok, I will try to reproduce it on our staging with a fresh DB, should I import the QB backup? or not?

Steve Luo [21/Nov/17 02:39 PM]
Thank you for help.

No import, just a clean database, and with some agents would be better. Use the same environment like your production server and agents.

Piotr Jedrys [21/Nov/17 03:01 PM]
I have just started QB on my own mashine, with clean DB, and have the same problem:

java.lang.reflect.InvocationTargetException
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at com.google.common.eventbus.EventHandler.handleEvent(EventHandler.java:74)
        at com.google.common.eventbus.SynchronizedEventHandler.handleEvent(SynchronizedEventHandler.java:45)
        at com.google.common.eventbus.EventBus.dispatch(EventBus.java:313)
        at com.google.common.eventbus.EventBus.dispatchQueuedEvents(EventBus.java:296)
        at com.google.common.eventbus.EventBus.post(EventBus.java:267)
        at com.pmease.quickbuild.plugin.measurement.core.poller.MeasurementPollingTask.execute(MeasurementPollingTask.java:57)
        at com.pmease.quickbuild.plugin.measurement.core.poller.MeasurementPollingTask.run(MeasurementPollingTask.java:109)
        at com.google.common.util.concurrent.AbstractExecutionThreadService$1$1.run(AbstractExecutionThreadService.java:52)
        at java.lang.Thread.run(Thread.java:748)
 Caused by: org.hibernate.exception.ConstraintViolationException: could not execute statement
        at org.hibernate.exception.internal.SQLExceptionTypeDelegate.convert(SQLExceptionTypeDelegate.java:72)
        at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49)
        at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:126)
        at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:112)
        at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:211)
        at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:62)
        at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3124)
        at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:3581)
        at org.hibernate.action.internal.EntityInsertAction.execute(EntityInsertAction.java:104)
        at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:465)
        at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:351)
        at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:350)
        at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:56)
        at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1258)
        at com.pmease.quickbuild.entitymanager.impl.DefaultMeasurementDataManager.flushAndClear(DefaultMeasurementDataManager.java:86)
        at com.pmease.quickbuild.entitymanager.impl.DefaultMeasurementDataManager.save(DefaultMeasurementDataManager.java:113)
        at com.pmease.quickbuild.plugin.measurement.core.reporter.MeasurementServerReporter.save(MeasurementServerReporter.java:105)
        at com.pmease.quickbuild.plugin.measurement.core.reporter.MeasurementServerReporter.run(MeasurementServerReporter.java:76)
        at com.pmease.quickbuild.plugin.measurement.core.repor

Steve Luo [21/Nov/17 03:06 PM]
what is your environment? OS, disk? and any agents?

Piotr Jedrys [21/Nov/17 03:10 PM]
We are using dockerized approach:

so everything is united under docker with
Linux 4.4.0-83-generic #106~14.04.1-Ubuntu SMP Mon Jun 26 18:10:19 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
installed on it

For QB 6.0.x it was working without problems, currently even when using clear DB, no agents connected , I can see that measurements from the master node are not working

Piotr Jedrys [21/Nov/17 03:14 PM]
As you can see it tries to push the same values for example on disk.usage:

2017-11-21 15:11:51,368 [MeasurementPollingTask] ERROR com.google.common.eventbus.EventBus.QuickBuild Application - Could not dispatch event: Node: [quickbuild-master-dev:8810], beginTime: [Tue N
ov 21 15:11:51 UTC 2017], endTime: [Tue Nov 21 15:11:51 UTC 2017]
 source=[quickbuild-master-dev:8810], metricName=[steps.waitingsTotal], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.0]
 source=[quickbuild-master-dev:8810], metricName=[web.rest.fiveMinuteRate], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.0]
----> source=[quickbuild-master-dev:8810], metricName=[disk.usage./], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.08526666755430508]
 source=[quickbuild-master-dev:8810], metricName=[builds.successfulRate], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.0]
 source=[quickbuild-master-dev:8810], metricName=[cpu.totalUsage], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.017573467674223343]
 source=[quickbuild-master-dev:8810], metricName=[buildrequests.processedTotal], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.0]
 source=[quickbuild-master-dev:8810], metricName=[web.download.oneMinuteRate], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[2.5812899986304503]
 source=[quickbuild-master-dev:8810], metricName=[disk.frees./opt/quickbuild], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[5.8174328832E10]
 source=[quickbuild-master-dev:8810], metricName=[builds.total], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.0]
 source=[quickbuild-master-dev:8810], metricName=[jvm.threadCount], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[89.0]
 source=[quickbuild-master-dev:8810], metricName=[web.upload.averageDuration], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.0]
 source=[quickbuild-master-dev:8810], metricName=[web.download.fifteenMinuteRate], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[4.900601942442881]
 source=[quickbuild-master-dev:8810], metricName=[memory.usage], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.5146279402453038]
 source=[quickbuild-master-dev:8810], metricName=[web.rpc.fiveMinuteRate], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[23.193595324912707]
 source=[quickbuild-master-dev:8810], metricName=[web.upload.fiveMinuteRate], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.0]
 source=[quickbuild-master-dev:8810], metricName=[steps.successfulOnNode], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.0]
 source=[quickbuild-master-dev:8810], metricName=[builds.failed], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.0]
 source=[quickbuild-master-dev:8810], metricName=[web.rpc.oneMinuteRate], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[32.33846350312917]
 source=[quickbuild-master-dev:8810], metricName=[web.download.fiveMinuteRate], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[9.038988781852984]
 source=[quickbuild-master-dev:8810], metricName=[jvm.gcTime], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.0]
 source=[quickbuild-master-dev:8810], metricName=[web.ui.fiveMinuteRate], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[3.14361176247683]
 source=[quickbuild-master-dev:8810], metricName=[web.ui.oneMinuteRate], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.49498770976847883]
 source=[quickbuild-master-dev:8810], metricName=[jvm.gcRuns], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.0]
 source=[quickbuild-master-dev:8810], metricName=[web.download.averageDuration], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[22.24468085106383]
----> source=[quickbuild-master-dev:8810], metricName=[disk.usage./], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.08526666755430508]
 source=[quickbuild-master-dev:8810], metricName=[network.txBytes], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[7.6817594E7]
 source=[quickbuild-master-dev:8810], metricName=[web.upload.oneMinuteRate], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.0]
 source=[quickbuild-master-dev:8810], metricName=[db.busyConnections], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.0]
 source=[quickbuild-master-dev:8810], metricName=[buildrequests.processingsTotal], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.0]
 source=[quickbuild-master-dev:8810], metricName=[steps.finishedOnNode], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.0]
 source=[quickbuild-master-dev:8810], metricName=[builds.averageWaitingDuration], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.0]
 source=[quickbuild-master-dev:8810], metricName=[web.rest.fifteenMinuteRate], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.0]
 source=[quickbuild-master-dev:8810], metricName=[jvm.memoryUsage], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.1732642578193656]
 source=[quickbuild-master-dev:8810], metricName=[web.rest.requests], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.0]
 source=[quickbuild-master-dev:8810], metricName=[disk.usage./opt/quickbuild], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.08526666755430508]
 source=[quickbuild-master-dev:8810], metricName=[web.rpc.fifteenMinuteRate], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[10.384748366379377]
 source=[quickbuild-master-dev:8810], metricName=[web.ui.fifteenMinuteRate], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[20.470406496636745]
 source=[quickbuild-master-dev:8810], metricName=[web.upload.fifteenMinuteRate], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.0]
 source=[quickbuild-master-dev:8810], metricName=[web.rest.oneMinuteRate], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.0]
 source=[quickbuild-master-dev:8810], metricName=[jetty.totalConnections], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[8.0]
 source=[quickbuild-master-dev:8810], metricName=[disk.usage./opt/quickbuild], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.08526666755430508]
 source=[quickbuild-master-dev:8810], metricName=[disk.frees./opt/quickbuild], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[5.8174328832E10]
 source=[quickbuild-master-dev:8810], metricName=[web.rest.averageDuration], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.0]
 source=[quickbuild-master-dev:8810], metricName=[buildrequests.submittedTotal], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.0]
 source=[quickbuild-master-dev:8810], metricName=[web.upload.requests], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.0]
 source=[quickbuild-master-dev:8810], metricName=[web.rpc.requests], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[182.0]
 source=[quickbuild-master-dev:8810], metricName=[jetty.usedConnections], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[3.0]
 source=[quickbuild-master-dev:8810], metricName=[db.numConnections], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[5.0]
 source=[quickbuild-master-dev:8810], metricName=[disk.frees./], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[5.8174328832E10]
 source=[quickbuild-master-dev:8810], metricName=[steps.runningsTotal], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[0.0]
 source=[quickbuild-master-dev:8810], metricName=[web.ui.requests], timestamp=[Tue Nov 21 15:11:51 UTC 2017], value=[9.0]

Piotr Jedrys [21/Nov/17 03:16 PM]
Oh, maybe I know what is the problem - the config for plugin, after upgrade it is doubled

monitdisk: /opt/buildagent/,C:/,D:/,/opt/,/opt/quickbuild/

Piotr Jedrys [21/Nov/17 03:17 PM]
and on my clear setup this is the only thing (except user) which I have changed and copied from our production env directly

Piotr Jedrys [21/Nov/17 03:32 PM]
no, even when specifying
monitdisk: /opt/buildagent/,C:/,D:/

it still fails

but when I specify empty monitdisk it works back ok.

Steve Luo [21/Nov/17 03:36 PM]
how about just /opt/buildagent/?

I saw you use both linux and windows directory here, I don't know if this is the problem. It would be better to use a variable in the plugin setting and set the value for this variable in your agent.

Steve Luo [21/Nov/17 03:37 PM]

Piotr Jedrys [22/Nov/17 10:46 AM]
I have done a workaround on my end, nevertheless I can still see problems when specifying multiple elements in this monitorDisks (if there is no such drive, constraint fails, or when it is doubled etc). You should fix this in the code in my opinion, so that you never send the multiple same values to the database.

Steve Luo [22/Nov/17 10:49 AM]
I have reproduced this issue and I will get it fixed in next patch release..