Skip to content

Commit 674668e

Browse files
author
Bart Koelman
committed
Added trace-level logging for the controller > service > repository chain
1 parent d5dbf72 commit 674668e

File tree

4 files changed

+69
-21
lines changed

4 files changed

+69
-21
lines changed

‎src/JsonApiDotNetCore/Controllers/BaseJsonApiController.cs

Lines changed: 16 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -1,12 +1,8 @@
1-
using System;
21
using System.Net.Http;
32
using System.Threading.Tasks;
43
using JsonApiDotNetCore.Configuration;
54
using JsonApiDotNetCore.Exceptions;
6-
using JsonApiDotNetCore.Extensions;
7-
using JsonApiDotNetCore.Internal;
85
using JsonApiDotNetCore.Models;
9-
using JsonApiDotNetCore.Models.JsonApiDocuments;
106
using JsonApiDotNetCore.Services;
117
using Microsoft.AspNetCore.Mvc;
128
using Microsoft.Extensions.Logging;
@@ -65,19 +61,21 @@ protected BaseJsonApiController(
6561
_update = update;
6662
_updateRelationships = updateRelationships;
6763
_delete = delete;
68-
69-
_logger.LogTrace("Executing constructor.");
7064
}
7165

7266
public virtual async Task<IActionResult> GetAsync()
7367
{
68+
_logger.LogTrace($"Entering {nameof(GetAsync)}().");
69+
7470
if (_getAll == null) throw new RequestMethodNotAllowedException(HttpMethod.Get);
7571
var entities = await _getAll.GetAsync();
7672
return Ok(entities);
7773
}
7874

7975
public virtual async Task<IActionResult> GetAsync(TId id)
8076
{
77+
_logger.LogTrace($"Entering {nameof(GetAsync)}('{id}').");
78+
8179
if (_getById == null) throw new RequestMethodNotAllowedException(HttpMethod.Get);
8280
var entity = await _getById.GetAsync(id);
8381
if (entity == null)
@@ -90,6 +88,8 @@ public virtual async Task<IActionResult> GetAsync(TId id)
9088

9189
public virtual async Task<IActionResult> GetRelationshipsAsync(TId id, string relationshipName)
9290
{
91+
_logger.LogTrace($"Entering {nameof(GetRelationshipsAsync)}('{id}', '{relationshipName}').");
92+
9393
if (_getRelationships == null) throw new RequestMethodNotAllowedException(HttpMethod.Get);
9494
var relationship = await _getRelationships.GetRelationshipsAsync(id, relationshipName);
9595
if (relationship == null)
@@ -102,13 +102,17 @@ public virtual async Task<IActionResult> GetRelationshipsAsync(TId id, string re
102102

103103
public virtual async Task<IActionResult> GetRelationshipAsync(TId id, string relationshipName)
104104
{
105+
_logger.LogTrace($"Entering {nameof(GetRelationshipAsync)}('{id}', '{relationshipName}').");
106+
105107
if (_getRelationship == null) throw new RequestMethodNotAllowedException(HttpMethod.Get);
106108
var relationship = await _getRelationship.GetRelationshipAsync(id, relationshipName);
107109
return Ok(relationship);
108110
}
109111

110112
public virtual async Task<IActionResult> PostAsync([FromBody] T entity)
111113
{
114+
_logger.LogTrace($"Entering {nameof(PostAsync)}({(entity == null ? "null" : "object")}).");
115+
112116
if (_create == null)
113117
throw new RequestMethodNotAllowedException(HttpMethod.Post);
114118

@@ -128,6 +132,8 @@ public virtual async Task<IActionResult> PostAsync([FromBody] T entity)
128132

129133
public virtual async Task<IActionResult> PatchAsync(TId id, [FromBody] T entity)
130134
{
135+
_logger.LogTrace($"Entering {nameof(PatchAsync)}('{id}', {(entity == null ? "null" : "object")}).");
136+
131137
if (_update == null) throw new RequestMethodNotAllowedException(HttpMethod.Patch);
132138
if (entity == null)
133139
return UnprocessableEntity();
@@ -148,13 +154,17 @@ public virtual async Task<IActionResult> PatchAsync(TId id, [FromBody] T entity)
148154

149155
public virtual async Task<IActionResult> PatchRelationshipsAsync(TId id, string relationshipName, [FromBody] object relationships)
150156
{
157+
_logger.LogTrace($"Entering {nameof(PatchRelationshipsAsync)}('{id}', '{relationshipName}', {(relationships == null ? "null" : "object")}).");
158+
151159
if (_updateRelationships == null) throw new RequestMethodNotAllowedException(HttpMethod.Patch);
152160
await _updateRelationships.UpdateRelationshipsAsync(id, relationshipName, relationships);
153161
return Ok();
154162
}
155163

156164
public virtual async Task<IActionResult> DeleteAsync(TId id)
157165
{
166+
_logger.LogTrace($"Entering {nameof(DeleteAsync)}('{id}).");
167+
158168
if (_delete == null) throw new RequestMethodNotAllowedException(HttpMethod.Delete);
159169
var wasDeleted = await _delete.DeleteAsync(id);
160170
if (!wasDeleted)

‎src/JsonApiDotNetCore/Data/DefaultResourceRepository.cs

Lines changed: 32 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -42,23 +42,30 @@ public DefaultResourceRepository(
4242
_context = contextResolver.GetContext();
4343
_dbSet = _context.Set<TResource>();
4444
_logger = loggerFactory.CreateLogger<DefaultResourceRepository<TResource, TId>>();
45-
46-
_logger.LogTrace("Executing constructor.");
4745
}
4846

4947
/// <inheritdoc />
5048
public virtual IQueryable<TResource> Get()
5149
{
50+
_logger.LogTrace($"Entering {nameof(Get)}().");
51+
5252
var resourceContext = _resourceGraph.GetResourceContext<TResource>();
5353
return EagerLoad(_dbSet, resourceContext.EagerLoads);
5454
}
5555

5656
/// <inheritdoc />
57-
public virtual IQueryable<TResource> Get(TId id) => Get().Where(e => e.Id.Equals(id));
57+
public virtual IQueryable<TResource> Get(TId id)
58+
{
59+
_logger.LogTrace($"Entering {nameof(Get)}('{id}').");
60+
61+
return Get().Where(e => e.Id.Equals(id));
62+
}
5863

5964
/// <inheritdoc />
6065
public virtual IQueryable<TResource> Select(IQueryable<TResource> entities, IEnumerable<AttrAttribute> fields = null)
6166
{
67+
_logger.LogTrace($"Entering {nameof(Select)}({nameof(entities)}, {nameof(fields)}).");
68+
6269
if (fields != null && fields.Any())
6370
return entities.Select(fields);
6471

@@ -68,6 +75,8 @@ public virtual IQueryable<TResource> Select(IQueryable<TResource> entities, IEnu
6875
/// <inheritdoc />
6976
public virtual IQueryable<TResource> Filter(IQueryable<TResource> entities, FilterQueryContext filterQueryContext)
7077
{
78+
_logger.LogTrace($"Entering {nameof(Filter)}({nameof(entities)}, {nameof(filterQueryContext)}).");
79+
7180
if (filterQueryContext.IsCustom)
7281
{
7382
var query = (Func<IQueryable<TResource>, FilterQuery, IQueryable<TResource>>)filterQueryContext.CustomQuery;
@@ -79,12 +88,16 @@ public virtual IQueryable<TResource> Filter(IQueryable<TResource> entities, Filt
7988
/// <inheritdoc />
8089
public virtual IQueryable<TResource> Sort(IQueryable<TResource> entities, SortQueryContext sortQueryContext)
8190
{
91+
_logger.LogTrace($"Entering {nameof(Sort)}({nameof(entities)}, {nameof(sortQueryContext)}).");
92+
8293
return entities.Sort(sortQueryContext);
8394
}
8495

8596
/// <inheritdoc />
8697
public virtual async Task<TResource> CreateAsync(TResource entity)
8798
{
99+
_logger.LogTrace($"Entering {nameof(CreateAsync)}({(entity == null ? "null" : "object")}).");
100+
88101
foreach (var relationshipAttr in _targetedFields.Relationships)
89102
{
90103
object trackedRelationshipValue = GetTrackedRelationshipValue(relationshipAttr, entity, out bool relationshipWasAlreadyTracked);
@@ -184,6 +197,8 @@ private void DetachRelationships(TResource entity)
184197
/// <inheritdoc />
185198
public virtual async Task<TResource> UpdateAsync(TResource updatedEntity)
186199
{
200+
_logger.LogTrace($"Entering {nameof(UpdateAsync)}({(updatedEntity == null ? "null" : "object")}).");
201+
187202
var databaseEntity = await Get(updatedEntity.Id).FirstOrDefaultAsync();
188203
if (databaseEntity == null)
189204
return null;
@@ -264,6 +279,8 @@ private IIdentifiable GetTrackedHasOneRelationshipValue(IIdentifiable relationsh
264279
/// <inheritdoc />
265280
public async Task UpdateRelationshipsAsync(object parent, RelationshipAttribute relationship, IEnumerable<string> relationshipIds)
266281
{
282+
_logger.LogTrace($"Entering {nameof(UpdateRelationshipsAsync)}({nameof(parent)}, {nameof(relationship)}, {nameof(relationshipIds)}).");
283+
267284
var typeToUpdate = (relationship is HasManyThroughAttribute hasManyThrough)
268285
? hasManyThrough.ThroughType
269286
: relationship.RightType;
@@ -277,6 +294,8 @@ public async Task UpdateRelationshipsAsync(object parent, RelationshipAttribute
277294
/// <inheritdoc />
278295
public virtual async Task<bool> DeleteAsync(TId id)
279296
{
297+
_logger.LogTrace($"Entering {nameof(DeleteAsync)}('{id}').");
298+
280299
var entity = await Get(id).FirstOrDefaultAsync();
281300
if (entity == null) return false;
282301
_dbSet.Remove(entity);
@@ -299,6 +318,8 @@ private IQueryable<TResource> EagerLoad(IQueryable<TResource> entities, IEnumera
299318

300319
public virtual IQueryable<TResource> Include(IQueryable<TResource> entities, IEnumerable<RelationshipAttribute> inclusionChain = null)
301320
{
321+
_logger.LogTrace($"Entering {nameof(Include)}({nameof(entities)}, {nameof(inclusionChain)}).");
322+
302323
if (inclusionChain == null || !inclusionChain.Any())
303324
{
304325
return entities;
@@ -321,6 +342,8 @@ public virtual IQueryable<TResource> Include(IQueryable<TResource> entities, IEn
321342
/// <inheritdoc />
322343
public virtual async Task<IEnumerable<TResource>> PageAsync(IQueryable<TResource> entities, int pageSize, int pageNumber)
323344
{
345+
_logger.LogTrace($"Entering {nameof(PageAsync)}({nameof(entities)}, {pageSize}, {pageNumber}).");
346+
324347
// the IQueryable returned from the hook executor is sometimes consumed here.
325348
// In this case, it does not support .ToListAsync(), so we use the method below.
326349
if (pageNumber >= 0)
@@ -351,6 +374,8 @@ public virtual async Task<IEnumerable<TResource>> PageAsync(IQueryable<TResource
351374
/// <inheritdoc />
352375
public async Task<int> CountAsync(IQueryable<TResource> entities)
353376
{
377+
_logger.LogTrace($"Entering {nameof(CountAsync)}({nameof(entities)}).");
378+
354379
if (entities is IAsyncEnumerable<TResource>)
355380
{
356381
return await entities.CountAsync();
@@ -361,6 +386,8 @@ public async Task<int> CountAsync(IQueryable<TResource> entities)
361386
/// <inheritdoc />
362387
public virtual async Task<TResource> FirstOrDefaultAsync(IQueryable<TResource> entities)
363388
{
389+
_logger.LogTrace($"Entering {nameof(FirstOrDefaultAsync)}({nameof(entities)}).");
390+
364391
return (entities is IAsyncEnumerable<TResource>)
365392
? await entities.FirstOrDefaultAsync()
366393
: entities.FirstOrDefault();
@@ -369,6 +396,8 @@ public virtual async Task<TResource> FirstOrDefaultAsync(IQueryable<TResource> e
369396
/// <inheritdoc />
370397
public async Task<IReadOnlyList<TResource>> ToListAsync(IQueryable<TResource> entities)
371398
{
399+
_logger.LogTrace($"Entering {nameof(ToListAsync)}({nameof(entities)}).");
400+
372401
if (entities is IAsyncEnumerable<TResource>)
373402
{
374403
return await entities.ToListAsync();

‎src/JsonApiDotNetCore/Extensions/IApplicationBuilderExtensions.cs

Lines changed: 1 addition & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -70,13 +70,7 @@ private static void LogResourceGraphValidations(IApplicationBuilder app)
7070

7171
if (logger != null)
7272
{
73-
resourceGraph?.ValidationResults.ForEach((v) =>
74-
logger.Log(
75-
v.LogLevel,
76-
new EventId(),
77-
v.Message,
78-
exception: null,
79-
formatter: (m, e) => m));
73+
resourceGraph?.ValidationResults.ForEach((v) => logger.Log(v.LogLevel, null, v.Message));
8074
}
8175
}
8276
}

‎src/JsonApiDotNetCore/Services/DefaultResourceService.cs

Lines changed: 20 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -54,12 +54,12 @@ public DefaultResourceService(
5454
_repository = repository;
5555
_hookExecutor = hookExecutor;
5656
_currentRequestResource = provider.GetResourceContext<TResource>();
57-
58-
_logger.LogTrace("Executing constructor.");
5957
}
6058

6159
public virtual async Task<TResource> CreateAsync(TResource entity)
6260
{
61+
_logger.LogTrace($"Entering {nameof(CreateAsync)}({(entity == null ? "null" : "object")}).");
62+
6363
entity = IsNull(_hookExecutor) ? entity : _hookExecutor.BeforeCreate(AsList(entity), ResourcePipeline.Post).SingleOrDefault();
6464
entity = await _repository.CreateAsync(entity);
6565

@@ -76,6 +76,8 @@ public virtual async Task<TResource> CreateAsync(TResource entity)
7676

7777
public virtual async Task<bool> DeleteAsync(TId id)
7878
{
79+
_logger.LogTrace($"Entering {nameof(DeleteAsync)}('{id}').");
80+
7981
var entity = typeof(TResource).New<TResource>();
8082
entity.Id = id;
8183
if (!IsNull(_hookExecutor, entity)) _hookExecutor.BeforeDelete(AsList(entity), ResourcePipeline.Delete);
@@ -86,6 +88,8 @@ public virtual async Task<bool> DeleteAsync(TId id)
8688

8789
public virtual async Task<IEnumerable<TResource>> GetAsync()
8890
{
91+
_logger.LogTrace($"Entering {nameof(GetAsync)}().");
92+
8993
_hookExecutor?.BeforeRead<TResource>(ResourcePipeline.Get);
9094

9195
var entityQuery = _repository.Get();
@@ -111,6 +115,8 @@ public virtual async Task<IEnumerable<TResource>> GetAsync()
111115

112116
public virtual async Task<TResource> GetAsync(TId id)
113117
{
118+
_logger.LogTrace($"Entering {nameof(GetAsync)}('{id}').");
119+
114120
var pipeline = ResourcePipeline.GetSingle;
115121
_hookExecutor?.BeforeRead<TResource>(pipeline, id.ToString());
116122

@@ -130,6 +136,8 @@ public virtual async Task<TResource> GetAsync(TId id)
130136
// triggered by GET /articles/1/relationships/{relationshipName}
131137
public virtual async Task<TResource> GetRelationshipsAsync(TId id, string relationshipName)
132138
{
139+
_logger.LogTrace($"Entering {nameof(GetRelationshipsAsync)}('{id}', '{relationshipName}').");
140+
133141
var relationship = GetRelationship(relationshipName);
134142

135143
// BeforeRead hook execution
@@ -159,13 +167,17 @@ public virtual async Task<TResource> GetRelationshipsAsync(TId id, string relati
159167
// triggered by GET /articles/1/{relationshipName}
160168
public virtual async Task<object> GetRelationshipAsync(TId id, string relationshipName)
161169
{
170+
_logger.LogTrace($"Entering {nameof(GetRelationshipAsync)}('{id}', '{relationshipName}').");
171+
162172
var relationship = GetRelationship(relationshipName);
163173
var resource = await GetRelationshipsAsync(id, relationshipName);
164174
return relationship.GetValue(resource);
165175
}
166176

167177
public virtual async Task<TResource> UpdateAsync(TId id, TResource entity)
168178
{
179+
_logger.LogTrace($"Entering {nameof(UpdateAsync)}('{id}', {(entity == null ? "null" : "object")}).");
180+
169181
entity = IsNull(_hookExecutor) ? entity : _hookExecutor.BeforeUpdate(AsList(entity), ResourcePipeline.Patch).SingleOrDefault();
170182
entity = await _repository.UpdateAsync(entity);
171183
if (!IsNull(_hookExecutor, entity))
@@ -179,6 +191,8 @@ public virtual async Task<TResource> UpdateAsync(TId id, TResource entity)
179191
// triggered by PATCH /articles/1/relationships/{relationshipName}
180192
public virtual async Task UpdateRelationshipsAsync(TId id, string relationshipName, object related)
181193
{
194+
_logger.LogTrace($"Entering {nameof(UpdateRelationshipsAsync)}('{id}', '{relationshipName}', {(related == null ? "null" : "object")}).");
195+
182196
var relationship = GetRelationship(relationshipName);
183197
var entityQuery = _repository.Include(_repository.Get(id), new[] { relationship });
184198
var entity = await _repository.FirstOrDefaultAsync(entityQuery);
@@ -202,8 +216,10 @@ public virtual async Task UpdateRelationshipsAsync(TId id, string relationshipNa
202216

203217
protected virtual async Task<IEnumerable<TResource>> ApplyPageQueryAsync(IQueryable<TResource> entities)
204218
{
205-
if (!(_pageService.PageSize > 0))
219+
if (_pageService.PageSize <= 0)
206220
{
221+
_logger.LogDebug("Fetching complete result set.");
222+
207223
return await _repository.ToListAsync(entities);
208224
}
209225

@@ -213,8 +229,7 @@ protected virtual async Task<IEnumerable<TResource>> ApplyPageQueryAsync(IQuerya
213229
pageOffset = -pageOffset;
214230
}
215231

216-
_logger.LogInformation($"Applying paging query. Fetching page {pageOffset} " +
217-
$"with {_pageService.PageSize} entities");
232+
_logger.LogDebug($"Fetching paged result set at page {pageOffset} with size {_pageService.PageSize}.");
218233

219234
return await _repository.PageAsync(entities, _pageService.PageSize, pageOffset);
220235
}

0 commit comments

Comments
 (0)