huanld/speckle-server
1
0
Fork 0
Code Issues Pull Requests Actions 1 Packages Projects Releases Wiki Activity

feat(logging): pass request logger to core/services/objects (#2599)

Browse Source 
* chore(logging): include additional detail on object upload logs

* allow max file size to be configurable

* feat(logging): add logger to core/services/objects

* fix log line

* fix tests

* typo

* fix variable name

* convert values to megabytes

* calculating memory was causing the system to freeze

* calculating memory was causing the system to freeze

* DRY the logging metadata

* all required variables should be passed to calculateLogMetadata

* fix many things with the logging
This commit is contained in:
Iain Sproat
2024-08-09 09:15:37 +01:00
committed by GitHub
parent 55cad9662a
commit ee3e9af78d
15 changed files with 207 additions and 145 deletions
Download Patch File Download Diff File Expand all files Collapse all files
packages/fileimport-service/ifc/api.js
+2 -2
View File
@@ -31,7 +31,7 @@ module.exports = class ServerAPI {
obj.id = crypto.createHash('md5').update(JSON.stringify(obj)).digest('hex')
}
await this.createObject(this.streamId, obj)
await this.createObject({ streamId: this.streamId, object: obj })
return obj.id
}
@@ -40,7 +40,7 @@ module.exports = class ServerAPI {
return await this.createObjectsBatched(this.streamId, objs)
}
async createObject(streamId, object) {
async createObject({ streamId, object }) {
const insertionObject = this.prepInsertionObject(streamId, object)
const closures = []
packages/server/modules/activitystream/tests/activity.spec.js
+2 -2
View File
@@ -129,7 +129,7 @@ describe('Activity @activity', () => {
streamSecret.id = resStream1.body.data.streamCreate
// create commit (cr2)
testObj2.id = await createObject(streamSecret.id, testObj2)
testObj2.id = await createObject({ streamId: streamSecret.id, object: testObj2 })
const resCommit1 = await sendRequest(userCr.token, {
query: `mutation { commitCreate(commit: {streamId: "${streamSecret.id}", branchName: "main", objectId: "${testObj2.id}", message: "first commit"})}`
})
@@ -152,7 +152,7 @@ describe('Activity @activity', () => {
branchPublic.id = resBranch.body.data.branchCreate
// create commit #2 (iz3)
testObj.id = await createObject(streamPublic.id, testObj)
testObj.id = await createObject({ streamId: streamPublic.id, object: testObj })
const resCommit2 = await sendRequest(userIz.token, {
query: `mutation { commitCreate(commit: { streamId: "${streamPublic.id}", branchName: "${branchPublic.name}", objectId: "${testObj.id}", message: "first commit" })}`
})
packages/server/modules/comments/tests/comments.graph.spec.js
+23 -11
View File
@@ -286,7 +286,7 @@ const queryComments = async ({ apollo, resources, shouldSucceed }) => {
bar: crs({ length: 5 })
}
const objectId = await createObject(resources.streamId, object)
const objectId = await createObject({ streamId: resources.streamId, object })
const numberOfComments = 3
const commentIds = await Promise.all(
@@ -361,9 +361,12 @@ const queryStreamCommentCount = async ({ apollo, resources, shouldSucceed }) =>
}
const queryObjectCommentCount = async ({ apollo, resources, shouldSucceed }) => {
const objectId = await createObject(resources.streamId, {
foo: 'bar',
noise: crs({ length: 5 })
const objectId = await createObject({
streamId: resources.streamId,
object: {
foo: 'bar',
noise: crs({ length: 5 })
}
})
await createComment({
userId: resources.testActorId,
@@ -394,9 +397,12 @@ const queryObjectCommentCount = async ({ apollo, resources, shouldSucceed }) =>
}
const queryCommitCommentCount = async ({ apollo, resources, shouldSucceed }) => {
const objectId = await createObject(resources.streamId, {
foo: 'bar',
notSignal: crs({ length: 10 })
const objectId = await createObject({
streamId: resources.streamId,
object: {
foo: 'bar',
notSignal: crs({ length: 10 })
}
})
const commitId = await createCommitByBranchName({
streamId: resources.streamId,
@@ -438,9 +444,12 @@ const queryCommitCollectionCommentCount = async ({
resources,
shouldSucceed
}) => {
const objectId = await createObject(resources.streamId, {
foo: 'bar',
almostMakesSense: crs({ length: 10 })
const objectId = await createObject({
streamId: resources.streamId,
object: {
foo: 'bar',
almostMakesSense: crs({ length: 10 })
}
})
const commitId = await createCommitByBranchName({
streamId: resources.streamId,
@@ -843,7 +852,10 @@ describe('Graphql @comments', () => {
})
}
const objectId = await createObject(stream.id, { test: 'object' })
const objectId = await createObject({
streamId: stream.id,
object: { test: 'object' }
})
const { id: commentId } = await createComment({
userId: myTestActor.id,
packages/server/modules/comments/tests/comments.spec.js
+38 -17
View File
@@ -105,8 +105,8 @@ describe('Comments @comments', () => {
stream.id = await createStream({ ...stream, ownerId: user.id })
testObject1.id = await createObject(stream.id, testObject1)
testObject2.id = await createObject(stream.id, testObject2)
testObject1.id = await createObject({ streamId: stream.id, object: testObject1 })
testObject2.id = await createObject({ streamId: stream.id, object: testObject2 })
commitId1 = await createCommitByBranchName({
streamId: stream.id,
@@ -163,7 +163,7 @@ describe('Comments @comments', () => {
const streamA = { name: 'Stream A' }
streamA.id = await createStream({ ...streamA, ownerId: user.id })
const objA = { foo: 'bar' }
objA.id = await createObject(streamA.id, objA)
objA.id = await createObject({ streamId: streamA.id, object: objA })
const commA = {}
commA.id = await createCommitByBranchName({
streamId: streamA.id,
@@ -177,7 +177,7 @@ describe('Comments @comments', () => {
const streamB = { name: 'Stream B' }
streamB.id = await createStream({ ...streamB, ownerId: otherUser.id })
const objB = { qux: 'mux' }
objB.id = await createObject(streamB.id, objB)
objB.id = await createObject({ streamId: streamB.id, object: objB })
const commB = {}
commB.id = await createCommitByBranchName({
streamId: streamB.id,
@@ -267,7 +267,7 @@ describe('Comments @comments', () => {
const stream = { name: 'Bean Counter' }
stream.id = await createStream({ ...stream, ownerId: user.id })
const obj = { foo: 'bar' }
obj.id = await createObject(stream.id, obj)
obj.id = await createObject({ streamId: stream.id, object: obj })
const commit = {}
commit.id = await createCommitByBranchName({
streamId: stream.id,
@@ -358,7 +358,7 @@ describe('Comments @comments', () => {
const streamOther = { name: 'Bean Counter' }
streamOther.id = await createStream({ ...streamOther, ownerId: user.id })
const objOther = { 'are you bored': 'yes' }
objOther.id = await createObject(streamOther.id, objOther)
objOther.id = await createObject({ streamId: streamOther.id, object: objOther })
const commitOther = {}
commitOther.id = await createCommitByBranchName({
streamId: streamOther.id,
@@ -560,7 +560,10 @@ describe('Comments @comments', () => {
})
it('Should not return the same comment multiple times for multi resource comments', async () => {
const localObjectId = await createObject(stream.id, { testObject: 1 })
const localObjectId = await createObject({
streamId: stream.id,
object: { testObject: 1 }
})
const commentCount = 3
for (let i = 0; i < commentCount; i++) {
@@ -600,8 +603,11 @@ describe('Comments @comments', () => {
})
it('Should handle cursor and limit for queries', async () => {
const localObjectId = await createObject(stream.id, {
testObject: 'something completely different'
const localObjectId = await createObject({
streamId: stream.id,
object: {
testObject: 'something completely different'
}
})
const createdComments = []
@@ -691,7 +697,10 @@ describe('Comments @comments', () => {
})
it('Should return all the referenced resources for a comment', async () => {
const localObjectId = await createObject(stream.id, { anotherTestObject: 1 })
const localObjectId = await createObject({
streamId: stream.id,
object: { anotherTestObject: 1 }
})
const inputResources = [
{ resourceId: stream.id, resourceType: 'stream' },
{ resourceId: commitId1, resourceType: 'commit' },
@@ -722,7 +731,10 @@ describe('Comments @comments', () => {
})
it('Should return the same data when querying a single comment vs a list of comments', async () => {
const localObjectId = await createObject(stream.id, { anotherTestObject: 42 })
const localObjectId = await createObject({
streamId: stream.id,
object: { anotherTestObject: 42 }
})
await createComment({
userId: user.id,
input: {
@@ -753,8 +765,11 @@ describe('Comments @comments', () => {
})
it('Should be able to edit a comment text', async () => {
const localObjectId = await createObject(stream.id, {
anotherTestObject: crs({ length: 10 })
const localObjectId = await createObject({
streamId: stream.id,
object: {
anotherTestObject: crs({ length: 10 })
}
})
const { id: commentId } = await createComment({
userId: user.id,
@@ -789,8 +804,11 @@ describe('Comments @comments', () => {
})
it('Should not be allowed to edit a comment of another user if its restricted', async () => {
const localObjectId = await createObject(stream.id, {
anotherTestObject: crs({ length: 10 })
const localObjectId = await createObject({
streamId: stream.id,
object: {
anotherTestObject: crs({ length: 10 })
}
})
const { id: commentId } = await createComment({
userId: user.id,
@@ -908,8 +926,11 @@ describe('Comments @comments', () => {
})
it('Should not query archived comments unless asked', async () => {
const localObjectId = await createObject(stream.id, {
testObject: crs({ length: 10 })
const localObjectId = await createObject({
streamId: stream.id,
object: {
testObject: crs({ length: 10 })
}
})
const commentCount = 15
packages/server/modules/core/graph/resolvers/objects.ts
+4 -4
View File
@@ -66,10 +66,10 @@ export = {
context.resourceAccessRules
)
const ids = await createObjects(
args.objectInput.streamId,
args.objectInput.objects
)
const ids = await createObjects({
streamId: args.objectInput.streamId,
objects: args.objectInput.objects
})
return ids
}
}
packages/server/modules/core/rest/upload.js
+66 -62
View File
@@ -159,39 +159,41 @@ module.exports = (app) => {
await Promise.all(promises)
}
const promise = objectInsertionService(req.params.streamId, objs).catch(
(e) => {
req.log.error(
{
...calculateLogMetadata({
batchSizeMb: gunzippedBufferMegabyteSize,
start,
batchStartTime,
totalObjectsProcessed
}),
objectCount: objs.length,
err: e
},
`Upload error when inserting objects into database. Number of objects: {objectCount}. This batch took {batchElapsedTimeMs}ms. Error occurred after {elapsedTimeMs}ms. Total objects processed before error: {totalObjectsProcessed}.`
)
if (!requestDropped) {
switch (e.constructor) {
case ObjectHandlingError:
res
.status(400)
.send(`Error inserting object in the database: ${e.message}`)
break
default:
res
.status(400)
.send(
'Error inserting object in the database. Check server logs for details'
)
}
const promise = objectInsertionService({
streamId: req.params.streamId,
objects: objs,
logger: req.log
}).catch((e) => {
req.log.error(
{
...calculateLogMetadata({
batchSizeMb: gunzippedBufferMegabyteSize,
start,
batchStartTime,
totalObjectsProcessed
}),
objectCount: objs.length,
err: e
},
`Upload error when inserting objects into database. Number of objects: {objectCount}. This batch took {batchElapsedTimeMs}ms. Error occurred after {elapsedTimeMs}ms. Total objects processed before error: {totalObjectsProcessed}.`
)
if (!requestDropped) {
switch (e.constructor) {
case ObjectHandlingError:
res
.status(400)
.send(`Error inserting object in the database: ${e.message}`)
break
default:
res
.status(400)
.send(
'Error inserting object in the database. Check server logs for details'
)
}
requestDropped = true
}
)
requestDropped = true
})
promises.push(promise)
await promise
@@ -296,37 +298,39 @@ module.exports = (app) => {
await Promise.all(promises)
}
const promise = objectInsertionService(req.params.streamId, objs).catch(
(e) => {
req.log.error(
{
...calculateLogMetadata({
batchSizeMb: toMegabytesWith1DecimalPlace(buffer.length),
start,
batchStartTime,
totalObjectsProcessed
}),
err: e
},
`Upload error when inserting objects into database. Number of objects: {objectCount}. This batch took {batchElapsedTimeMs}ms. Error occurred after {elapsedTimeMs}ms. Total objects processed before error: {totalObjectsProcessed}.`
)
if (!requestDropped)
switch (e.constructor) {
case ObjectHandlingError:
res
.status(400)
.send(`Error inserting object in the database. ${e.message}`)
break
default:
res
.status(400)
.send(
'Error inserting object in the database. Check server logs for details'
)
}
requestDropped = true
}
)
const promise = objectInsertionService({
streamId: req.params.streamId,
objects: objs,
logger: req.log
}).catch((e) => {
req.log.error(
{
...calculateLogMetadata({
batchSizeMb: toMegabytesWith1DecimalPlace(buffer.length),
start,
batchStartTime,
totalObjectsProcessed
}),
err: e
},
`Upload error when inserting objects into database. Number of objects: {objectCount}. This batch took {batchElapsedTimeMs}ms. Error occurred after {elapsedTimeMs}ms. Total objects processed before error: {totalObjectsProcessed}.`
)
if (!requestDropped)
switch (e.constructor) {
case ObjectHandlingError:
res
.status(400)
.send(`Error inserting object in the database. ${e.message}`)
break
default:
res
.status(400)
.send(
'Error inserting object in the database. Check server logs for details'
)
}
requestDropped = true
})
promises.push(promise)
await promise
packages/server/modules/core/services/objects.js
+23 -21
View File
@@ -17,9 +17,10 @@ const Closures = () => knex('object_children_closure')
module.exports = {
/**
* @param {{streamId, object, logger?}} params
* @returns {Promise<string>}
*/
async createObject(streamId, object) {
async createObject({ streamId, object, logger = servicesLogger }) {
const insertionObject = prepInsertionObject(streamId, object)
const closures = []
@@ -57,10 +58,12 @@ module.exports = {
}
}
logger.debug({ objectId: insertionObject.id }, 'Inserted object: {objectId}')
return insertionObject.id
},
async createObjectsBatched(streamId, objects) {
async createObjectsBatched({ streamId, objects, logger = servicesLogger }) {
const closures = []
const objsToInsert = []
const ids = []
@@ -112,10 +115,7 @@ module.exports = {
for (const batch of batches) {
prepInsertionObjectBatch(batch)
await Objects().insert(batch).onConflict().ignore()
servicesLogger.info(
{ objectCount: batch.length },
'Inserted ${objectCount} objects'
)
logger.info({ objectCount: batch.length }, 'Inserted {objectCount} objects')
}
}
@@ -126,16 +126,17 @@ module.exports = {
for (const batch of batches) {
prepInsertionClosureBatch(batch)
await Closures().insert(batch).onConflict().ignore()
servicesLogger.info(
{ batchLength: batch.length },
'Inserted ${batchLength} closures'
)
logger.info({ batchLength: batch.length }, 'Inserted {batchLength} closures')
}
}
return true
},
async createObjectsBatchedAndNoClosures(streamId, objects) {
async createObjectsBatchedAndNoClosures({
streamId,
objects,
logger = servicesLogger
}) {
const objsToInsert = []
const ids = []
@@ -159,10 +160,7 @@ module.exports = {
for (const batch of batches) {
prepInsertionObjectBatch(batch)
await Objects().insert(batch).onConflict().ignore()
servicesLogger.info(
{ batchLength: batch.length },
'Inserted {batchLength} objects'
)
logger.info({ batchLength: batch.length }, 'Inserted {batchLength} objects.')
}
}
@@ -172,7 +170,7 @@ module.exports = {
/**
* @returns {Promise<string[]>}
*/
async createObjects(streamId, objects) {
async createObjects({ streamId, objects, logger = servicesLogger }) {
// TODO: Switch to knex batch inserting functionality
// see http://knexjs.org/#Utility-BatchInsert
const batches = []
@@ -236,12 +234,16 @@ module.exports = {
}
const t1 = performance.now()
servicesLogger.info(
`Batch ${index + 1}/${batches.length}: Stored ${
closures.length + objsToInsert.length
} objects in ${t1 - t0}ms.`
logger.info(
{
batchIndex: index + 1,
totalCountOfBatches: batches.length,
countStoredObjects: closures.length + objsToInsert.length,
elapsedTimeMs: t1 - t0
},
'Batch {batchIndex}/{totalCountOfBatches}: Stored {countStoredObjects} objects in {elapsedTimeMs}ms.'
)
// logger.debug( `Batch ${index + 1}/${batches.length}: Stored ${closures.length + objsToInsert.length} objects in ${t1-t0}ms.` )
}
const promises = batches.map((batch, index) => insertBatch(batch, index))
packages/server/modules/core/tests/branches.spec.js
+1 -1
View File
@@ -47,7 +47,7 @@ describe('Branches @core-branches', () => {
user.id = await createUser(user)
stream.id = await createStream({ ...stream, ownerId: user.id })
testObject.id = await createObject(stream.id, testObject)
testObject.id = await createObject({ streamId: stream.id, object: testObject })
})
const branch = { name: 'dim/dev' }
packages/server/modules/core/tests/commits.spec.js
+12 -6
View File
@@ -50,7 +50,7 @@ describe('Commits @core-commits', () => {
}
const generateObject = async (streamId = stream.id, object = testObject) =>
await createObject(streamId, object)
await createObject({ streamId, object })
const generateStream = async (streamBase = stream, ownerId = user.id) =>
await createStream({ ...streamBase, ownerId })
@@ -62,9 +62,15 @@ describe('Commits @core-commits', () => {
user.id = await createUser(user)
stream.id = await createStream({ ...stream, ownerId: user.id })
const testObjectId = await createObject(stream.id, testObject)
const testObject2Id = await createObject(stream.id, testObject2)
const testObject3Id = await createObject(stream.id, testObject3)
const testObjectId = await createObject({ streamId: stream.id, object: testObject })
const testObject2Id = await createObject({
streamId: stream.id,
object: testObject2
})
const testObject3Id = await createObject({
streamId: stream.id,
object: testObject3
})
commitId1 = await createCommitByBranchName({
streamId: stream.id,
@@ -212,7 +218,7 @@ describe('Commits @core-commits', () => {
for (let i = 0; i < 10; i++) {
const t = { qux: i }
t.id = await createObject(streamId, t)
t.id = await createObject({ streamId, object: t })
await createCommitByBranchName({
streamId,
branchName: 'main',
@@ -252,7 +258,7 @@ describe('Commits @core-commits', () => {
for (let i = 0; i < 15; i++) {
const t = { thud: i }
t.id = await createObject(streamId, t)
t.id = await createObject({ streamId, object: t })
await createCommitByBranchName({
streamId,
branchName: 'dim/dev',
packages/server/modules/core/tests/objects.spec.js
+13 -10
View File
@@ -63,8 +63,8 @@ describe('Objects @core-objects', () => {
})
it('Should create objects', async () => {
sampleObject.id = await createObject(stream.id, sampleObject)
sampleCommit.id = await createObject(stream.id, sampleCommit)
sampleObject.id = await createObject({ streamId: stream.id, object: sampleObject })
sampleCommit.id = await createObject({ streamId: stream.id, object: sampleCommit })
})
const objCount_1 = 10
@@ -80,7 +80,7 @@ describe('Objects @core-objects', () => {
})
}
const ids = await createObjects(stream.id, objs)
const ids = await createObjects({ streamId: stream.id, objects: objs })
expect(ids).to.have.lengthOf(objCount_1)
}).timeout(30000)
@@ -109,7 +109,7 @@ describe('Objects @core-objects', () => {
})
}
const myIds = await createObjects(stream.id, objs2)
const myIds = await createObjects({ streamId: stream.id, objects: objs2 })
myIds.forEach((h, i) => (objs2[i].id = h))
@@ -127,7 +127,7 @@ describe('Objects @core-objects', () => {
return obj
}, {})
}
const id = await createObject(stream.id, obj)
const id = await createObject({ streamId: stream.id, object: obj })
expect(id).to.be.ok
})
@@ -156,16 +156,16 @@ describe('Objects @core-objects', () => {
it('Should get object children', async () => {
const objs_1 = createManyObjects(100, 'noise__')
const ids = await createObjects(stream.id, objs_1)
const ids = await createObjects({ streamId: stream.id, objects: objs_1 })
// console.log( ids )
// console.log(ids[ 0 ])
// The below are just performance benchmarking.
// let objs_2 = createManyObjects( 20000, 'noise_2' )
// let ids2 = await createObjects( objs_2 )
// let ids2 = await createObjects( {streamId: stream.id, objects: objs_2} )
// let objs_3 = createManyObjects( 100000, 'noise_3' )
// let ids3 = await createObjects( objs_3 )
// let ids3 = await createObjects( {streamId: stream.id, objects: objs_3} )
// let { rows } = await getObjectChildren( { objectId: ids[0], select: ['id', 'name', 'sortValueB'] } )
// let { rows } = await getObjectChildren( { objectId: ids[ 0 ] } )
@@ -494,7 +494,7 @@ describe('Objects @core-objects', () => {
const objs = createManyObjects(3333, 'perlin merlin magic')
commitId = objs[0].id
await createObjectsBatched(stream.id, objs)
await createObjectsBatched({ streamId: stream.id, objects: objs })
const parent = await getObject({ streamId: stream.id, objectId: commitId })
expect(parent.totalChildrenCount).to.equal(3333)
@@ -539,7 +539,10 @@ describe('Objects @core-objects', () => {
const promisses = []
for (let i = 0; i < shuffledVersions.length; i++) {
const promise = createObjectsBatched(stream.id, shuffledVersions[i])
const promise = createObjectsBatched({
streamId: stream.id,
objects: shuffledVersions[i]
})
promise.catch(() => {})
promisses.push(promise)
}
packages/server/modules/core/tests/streams.spec.ts
+4 -1
View File
@@ -341,7 +341,10 @@ describe('Streams @core-streams', () => {
it('Should update stream updatedAt on commit operations ', async () => {
const testObject = { foo: 'bar', baz: 'qux', id: '' }
testObject.id = await createObject(updatableStream.id, testObject)
testObject.id = await createObject({
streamId: updatableStream.id,
object: testObject
})
await createCommitByBranchName({
streamId: updatableStream.id,
packages/server/modules/core/tests/users.spec.js
+4 -1
View File
@@ -141,7 +141,10 @@ describe('Actors & Tokens @user-services', () => {
})
// create an object and a commit around it on the multiowner stream
const objId = await createObject(multiOwnerStream.id, { pie: 'in the sky' })
const objId = await createObject({
streamId: multiOwnerStream.id,
object: { pie: 'in the sky' }
})
const commitId = await createCommitByBranchName({
streamId: multiOwnerStream.id,
branchName: 'ballmer/dev',
packages/server/modules/cross-server-sync/services/commit.ts
+7 -4
View File
@@ -495,10 +495,13 @@ const createNewObject = async (
return
}
const newObjectId = await createObject(targetStreamId, {
...newObject,
id: newObject.id,
speckleType: newObject.speckleType || newObject.speckle_type || 'Base'
const newObjectId = await createObject({
streamId: targetStreamId,
object: {
...newObject,
id: newObject.id,
speckleType: newObject.speckleType || newObject.speckle_type || 'Base'
}
})
const newRecord = await getObject(newObjectId, targetStreamId)
packages/server/modules/stats/tests/stats.spec.js
+4 -1
View File
@@ -230,7 +230,10 @@ async function seedDb({
const streamIds = await Promise.all(streamPromises)
// create a objects
const objs = await createObjects(streamIds[0], createManyObjects(numObjects - 1))
const objs = await createObjects({
streamId: streamIds[0],
objects: createManyObjects(numObjects - 1)
})
// create commits referencing those objects
const commitPromises = []
packages/server/test/speckle-helpers/commitHelper.ts
+4 -2
View File
@@ -36,7 +36,7 @@ export type BasicTestCommit = {
}
export async function createTestObject(params: { projectId: string }) {
return await createObject(params.projectId, { foo: 'bar' })
return await createObject({ streamId: params.projectId, object: { foo: 'bar' } })
}
/**
@@ -46,7 +46,9 @@ async function ensureObjects(commits: BasicTestCommit[]) {
const commitsWithoutObjects = commits.filter((c) => !c.objectId)
await Promise.all(
commitsWithoutObjects.map((c) =>
createObject(c.streamId, { foo: 'bar' }).then((oid) => (c.objectId = oid))
createObject({ streamId: c.streamId, object: { foo: 'bar' } }).then(
(oid) => (c.objectId = oid)
)
)
)
}