Skip to content

Commit 57f2d09

Browse files
breardon2011breardon2011
committed
logging for create timing
1 parent 14144b9 commit 57f2d09

File tree

7 files changed

+122
-24
lines changed

7 files changed

+122
-24
lines changed

‎taco/internal/repositories/unit_repository.go‎

Lines changed: 34 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -39,27 +39,48 @@ func NewUnitRepository(db *gorm.DB, blobStore storage.UnitStore) *UnitRepository
3939

4040
// Create creates a new unit with UUID and org-scoped storage
4141
func (r *UnitRepository) Create(ctx context.Context, orgID, name string) (*storage.UnitMetadata, error) {
42+
startRepo := time.Now()
43+
44+
// Extract request ID from context if available (passed through from handler)
45+
requestID := "repo"
46+
if ctx.Value("request-id") != nil {
47+
if rid, ok := ctx.Value("request-id").(string); ok {
48+
requestID = rid
49+
}
50+
}
51+
52+
log.Printf("[%s] 💾 REPOSITORY: Starting Create (org: %s, name: %s)", requestID, orgID, name)
53+
4254
// Get organization to validate and get org name
55+
orgLookupStart := time.Now()
4356
var org types.Organization
4457
if err := r.db.WithContext(ctx).Where(queryByID, orgID).First(&org).Error; err != nil {
58+
log.Printf("[%s] ❌ REPOSITORY: Org lookup failed (+%dms) - %v", requestID, time.Since(startRepo).Milliseconds(), err)
4559
if errors.Is(err, gorm.ErrRecordNotFound) {
4660
return nil, fmt.Errorf("organization not found: %s", orgID)
4761
}
4862
return nil, fmt.Errorf(errMsgOrgNotFound, err)
4963
}
64+
orgLookupTime := time.Since(orgLookupStart)
65+
log.Printf("[%s] ✅ REPOSITORY: Org found '%s' (%dms)", requestID, org.Name, orgLookupTime.Milliseconds())
5066

5167
// Check if unit already exists
68+
checkExistStart := time.Now()
5269
var existing types.Unit
5370
err := r.db.WithContext(ctx).
5471
Where("org_id = ? AND name = ?", orgID, name).
5572
First(&existing).Error
73+
checkExistTime := time.Since(checkExistStart)
5674

5775
if err == nil {
76+
log.Printf("[%s] ⚠️ REPOSITORY: Unit already exists (check: %dms, total: %dms)", requestID, checkExistTime.Milliseconds(), time.Since(startRepo).Milliseconds())
5877
return nil, storage.ErrAlreadyExists
5978
}
6079
if !errors.Is(err, gorm.ErrRecordNotFound) {
80+
log.Printf("[%s] ❌ REPOSITORY: Error checking existing unit (+%dms) - %v", requestID, time.Since(startRepo).Milliseconds(), err)
6181
return nil, fmt.Errorf("failed to check existing unit: %w", err)
6282
}
83+
log.Printf("[%s] ✅ REPOSITORY: Unit name available (check: %dms)", requestID, checkExistTime.Milliseconds())
6384

6485
// Create database record (UUID auto-generated by BeforeCreate hook)
6586
now := time.Now()
@@ -71,7 +92,9 @@ func (r *UnitRepository) Create(ctx context.Context, orgID, name string) (*stora
7192
Locked: false,
7293
}
7394

95+
dbCreateStart := time.Now()
7496
if err := r.db.WithContext(ctx).Create(unit).Error; err != nil {
97+
log.Printf("[%s] ❌ REPOSITORY: DB create failed (attempt: %dms, total: %dms) - %v", requestID, time.Since(dbCreateStart).Milliseconds(), time.Since(startRepo).Milliseconds(), err)
7598
// Check if this is a unique constraint violation
7699
// GORM doesn't have a specific error type, so we check the error string
77100
errMsg := err.Error()
@@ -83,6 +106,8 @@ func (r *UnitRepository) Create(ctx context.Context, orgID, name string) (*stora
83106
}
84107
return nil, fmt.Errorf("failed to create unit in database: %w", err)
85108
}
109+
dbCreateTime := time.Since(dbCreateStart)
110+
log.Printf("[%s] ✅ REPOSITORY: DB record created with UUID %s (db_insert: %dms)", requestID, unit.ID, dbCreateTime.Milliseconds())
86111

87112
// Construct UUID-based blob path: {org-uuid}/{unit-uuid}
88113
// This is immutable - unit renames won't affect S3 paths
@@ -91,20 +116,24 @@ func (r *UnitRepository) Create(ctx context.Context, orgID, name string) (*stora
91116
// Create blob in storage ASYNCHRONOUSLY for faster response
92117
// The unit is usable even if S3 isn't ready yet (first terraform apply will initialize it)
93118
go func() {
119+
s3Start := time.Now()
94120
// Use background context to avoid cancellation
95121
bgCtx := context.Background()
96122
_, err := r.blobStore.Create(bgCtx, blobPath)
123+
s3Time := time.Since(s3Start)
97124
if err != nil {
98-
log.Printf("⚠️ Async S3 creation failed for unit %s (%s/%s): %v - will be created on first use",
99-
unit.ID, org.ID, unit.ID, err)
125+
log.Printf("[%s] ⚠️ REPOSITORY: Async S3 creation failed for unit %s after %dms: %v - will be created on first use",
126+
requestID, unit.ID, s3Time.Milliseconds(), err)
100127
// Note: Unit remains in DB even if S3 fails - terraform apply will create the state file
101128
} else {
102-
log.Printf("✅ Async S3 blob created for unit %s (%s/%s)", unit.ID, org.ID, unit.ID)
129+
log.Printf("[%s] ✅ REPOSITORY: Async S3 blob created for unit %s (%s/%s) in %dms",
130+
requestID, unit.ID, org.ID, unit.ID, s3Time.Milliseconds())
103131
}
104132
}()
105133

106-
log.Printf("Created unit: UUID=%s, Org=%s (%s), Name=%s, BlobPath=%s (S3 creating async)",
107-
unit.ID, org.Name, org.ID, name, blobPath)
134+
totalRepoTime := time.Since(startRepo)
135+
log.Printf("[%s] ✅ REPOSITORY: Complete - total: %dms (org_lookup: %dms, exist_check: %dms, db_insert: %dms, s3: async)",
136+
requestID, totalRepoTime.Milliseconds(), orgLookupTime.Milliseconds(), checkExistTime.Milliseconds(), dbCreateTime.Milliseconds())
108137

109138
return &storage.UnitMetadata{
110139
ID: unit.ID, // UUID

‎taco/internal/unit/handler.go‎

Lines changed: 35 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -88,13 +88,29 @@ type CreateUnitResponse struct {
8888
}
8989

9090
func (h *Handler) CreateUnit(c echo.Context) error {
91+
startHandler := time.Now()
92+
93+
// Extract request ID for end-to-end tracing
94+
requestID := c.Request().Header.Get("X-Request-ID")
95+
if requestID == "" {
96+
requestID = fmt.Sprintf("backend-%d", time.Now().UnixNano())
97+
}
98+
99+
c.Logger().Infof("[%s] 🔶 BACKEND: Received create unit request", requestID)
100+
91101
var req CreateUnitRequest
102+
bindStart := time.Now()
92103
if err := c.Bind(&req); err != nil {
104+
c.Logger().Errorf("[%s] ❌ BACKEND: Failed to bind request body - %v (+%dms)", requestID, err, time.Since(startHandler).Milliseconds())
93105
analytics.SendEssential("unit_create_failed_invalid_request")
94106
return c.JSON(http.StatusBadRequest, map[string]string{"error": "Invalid request body"})
95107
}
108+
bindTime := time.Since(bindStart)
109+
110+
c.Logger().Infof("[%s] 📋 BACKEND: Parsed request for unit '%s' (bind: %dms)", requestID, req.Name, bindTime.Milliseconds())
96111

97112
if err := domain.ValidateUnitID(req.Name); err != nil {
113+
c.Logger().Errorf("[%s] ❌ BACKEND: Invalid unit name '%s' - %v (+%dms)", requestID, req.Name, err, time.Since(startHandler).Milliseconds())
98114
analytics.SendEssential("unit_create_failed_invalid_name")
99115
return c.JSON(http.StatusBadRequest, map[string]string{"error": err.Error()})
100116
}
@@ -104,21 +120,28 @@ func (h *Handler) CreateUnit(c echo.Context) error {
104120
ctx := c.Request().Context()
105121
orgCtx, ok := domain.OrgFromContext(ctx)
106122
if !ok {
123+
c.Logger().Errorf("[%s] ❌ BACKEND: Organization context missing (+%dms)", requestID, time.Since(startHandler).Milliseconds())
107124
analytics.SendEssential("unit_create_failed_no_org_context")
108125
return c.JSON(http.StatusInternalServerError, map[string]string{"error": "Organization context missing"})
109126
}
127+
128+
c.Logger().Infof("[%s] 🗄️ BACKEND: Calling repository Create (org: %s, name: %s)", requestID, orgCtx.OrgID, name)
110129

130+
createStart := time.Now()
111131
metadata, err := h.store.Create(ctx, orgCtx.OrgID, name)
132+
createTime := time.Since(createStart)
133+
112134
if err != nil {
113135
if err == storage.ErrAlreadyExists {
136+
c.Logger().Warnf("[%s] ⚠️ BACKEND: Unit already exists (repo: %dms, total: %dms)", requestID, createTime.Milliseconds(), time.Since(startHandler).Milliseconds())
114137
analytics.SendEssential("unit_create_failed_already_exists")
115138
return c.JSON(http.StatusConflict, map[string]string{
116139
"error": "Unit already exists",
117140
"detail": fmt.Sprintf("A unit with name '%s' already exists in this organization", name),
118141
})
119142
}
120143
// Log the actual error for debugging
121-
c.Logger().Errorf("Failed to create unit '%s' in org '%s': %v", name, orgCtx.OrgID, err)
144+
c.Logger().Errorf("[%s] ❌ BACKEND: Repository error (repo: %dms, total: %dms) - %v", requestID, createTime.Milliseconds(), time.Since(startHandler).Milliseconds(), err)
122145
analytics.SendEssential("unit_create_failed_storage_error")
123146
// Surface the actual error message to help with debugging
124147
return c.JSON(http.StatusInternalServerError, map[string]string{
@@ -127,6 +150,17 @@ func (h *Handler) CreateUnit(c echo.Context) error {
127150
})
128151
}
129152

153+
totalTime := time.Since(startHandler)
154+
155+
// Log timing breakdown
156+
if totalTime.Milliseconds() > 3000 {
157+
c.Logger().Warnf("[%s] 🔥 BACKEND: VERY SLOW - total: %dms (bind: %dms, repo: %dms)", requestID, totalTime.Milliseconds(), bindTime.Milliseconds(), createTime.Milliseconds())
158+
} else if totalTime.Milliseconds() > 1000 {
159+
c.Logger().Warnf("[%s] ⚠️ BACKEND: SLOW - total: %dms (bind: %dms, repo: %dms)", requestID, totalTime.Milliseconds(), bindTime.Milliseconds(), createTime.Milliseconds())
160+
} else {
161+
c.Logger().Infof("[%s] ✅ BACKEND: Success - total: %dms (bind: %dms, repo: %dms)", requestID, totalTime.Milliseconds(), bindTime.Milliseconds(), createTime.Milliseconds())
162+
}
163+
130164
analytics.SendEssential("unit_created")
131165
return c.JSON(http.StatusCreated, CreateUnitResponse{ID: metadata.ID, Created: metadata.Updated})
132166
}

‎ui/server-start.js‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -163,7 +163,8 @@ const server = createServer(async (req, res) => {
163163
res.setHeader('Content-Encoding', 'gzip');
164164
res.removeHeader('Content-Length'); // Let gzip set the correct length
165165

166-
const gzip = createGzip();
166+
// Optimize gzip: level 6 = good compression/speed balance, memLevel 8 = more memory for speed
167+
const gzip = createGzip({ level: 6, memLevel: 8 });
167168
gzip.pipe(res);
168169

169170
const reader = response.body.getReader();

‎ui/src/api/statesman_serverFunctions.ts‎

Lines changed: 15 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -76,20 +76,25 @@ export const getUnitStatusFn = createServerFn({method: 'GET'})
7676
})
7777

7878
export const createUnitFn = createServerFn({method: 'POST'})
79-
.inputValidator((data : {userId: string, organisationId: string, email: string, name: string}) => data)
79+
.inputValidator((data : {userId: string, organisationId: string, email: string, name: string, requestId?: string}) => data)
8080
.handler(async ({ data }) => {
81-
const startCreate = Date.now();
82-
console.log(`🔵 Starting unit creation: "${data.name}" for org ${data.organisationId}`);
81+
const requestId = data.requestId || `unit-${Date.now()}-server`
82+
const startServerFn = Date.now();
8383

84-
const unit : any = await createUnit(data.organisationId, data.userId, data.email, data.name);
84+
console.log(`[${requestId}] 🔷 SERVER_FN: Received create unit request for "${data.name}" (org: ${data.organisationId})`);
8585

86-
const createTime = Date.now() - startCreate;
87-
if (createTime > 3000) {
88-
console.log(`🔥 VERY SLOW unit creation: "${data.name}" took ${createTime}ms`);
89-
} else if (createTime > 1000) {
90-
console.log(`⚠️ SLOW unit creation: "${data.name}" took ${createTime}ms`);
86+
const apiCallStart = Date.now();
87+
const unit : any = await createUnit(data.organisationId, data.userId, data.email, data.name, requestId);
88+
const apiCallTime = Date.now() - apiCallStart;
89+
90+
const totalServerTime = Date.now() - startServerFn;
91+
92+
if (totalServerTime > 3000) {
93+
console.log(`[${requestId}] 🔥 SERVER_FN: VERY SLOW - total: ${totalServerTime}ms (api: ${apiCallTime}ms)`);
94+
} else if (totalServerTime > 1000) {
95+
console.log(`[${requestId}] ⚠️ SERVER_FN: SLOW - total: ${totalServerTime}ms (api: ${apiCallTime}ms)`);
9196
} else {
92-
console.log(`✅ Unit created: "${data.name}" in ${createTime}ms`);
97+
console.log(`[${requestId}] ✅ SERVER_FN: Completed - total: ${totalServerTime}ms (api: ${apiCallTime}ms)`);
9398
}
9499

95100
return unit;

‎ui/src/api/statesman_units.ts‎

Lines changed: 17 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -169,9 +169,13 @@ export async function getUnitStatus(orgId: string, userId: string, email: string
169169
return response.json();
170170
}
171171

172-
export async function createUnit(orgId: string, userId: string, email: string, name: string) {
173-
const startFetch = Date.now();
172+
export async function createUnit(orgId: string, userId: string, email: string, name: string, requestId?: string) {
173+
const rid = requestId || `unit-${Date.now()}-api`
174+
const startApi = Date.now();
174175

176+
console.log(`[${rid}] 🌐 API_LAYER: Making HTTP POST to Statesman backend`);
177+
178+
const fetchStart = Date.now();
175179
const response = await fetch(`${process.env.STATESMAN_BACKEND_URL}/internal/api/units`, {
176180
method: 'POST',
177181
headers: {
@@ -180,26 +184,34 @@ export async function createUnit(orgId: string, userId: string, email: string, n
180184
'X-Org-ID': orgId,
181185
'X-User-ID': userId,
182186
'X-Email': email,
187+
'X-Request-ID': rid, // Pass request ID to backend for correlation
183188
},
184189
body: JSON.stringify({
185190
name: name,
186191
}),
187192
});
188193

189-
const fetchTime = Date.now() - startFetch;
190-
console.log(` → Statesman API call took ${fetchTime}ms (status: ${response.status})`);
194+
const fetchTime = Date.now() - fetchStart;
195+
const statusEmoji = response.ok ? '✅' : '❌';
196+
console.log(`[${rid}] ${statusEmoji} API_LAYER: Statesman responded - status: ${response.status}, time: ${fetchTime}ms`);
191197

192198
if (!response.ok) {
199+
const errorBody = await response.text().catch(() => 'Unknown error');
200+
console.error(`[${rid}] ❌ API_LAYER: Backend error - ${response.status} ${response.statusText}: ${errorBody}`);
193201
throw new Error(`Failed to create unit: ${response.statusText}`);
194202
}
195203

196204
const parseStart = Date.now();
197205
const result = await response.json();
198206
const parseTime = Date.now() - parseStart;
207+
208+
const totalApiTime = Date.now() - startApi;
199209

200210
if (parseTime > 100) {
201-
console.log(` → JSON parsing took ${parseTime}ms`);
211+
console.log(`[${rid}] 📄 API_LAYER: JSON parse took ${parseTime}ms`);
202212
}
213+
214+
console.log(`[${rid}] ✅ API_LAYER: Complete - total: ${totalApiTime}ms (fetch: ${fetchTime}ms, parse: ${parseTime}ms)`);
203215

204216
return result;
205217
}

‎ui/src/components/UnitCreateForm.tsx‎

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -38,25 +38,38 @@ export default function UnitCreateForm({
3838
setIsCreating(true)
3939
setError(null)
4040

41+
// Generate request ID for end-to-end tracing
42+
const requestId = `unit-${Date.now()}-${Math.random().toString(36).slice(2, 8)}`
43+
const startTime = Date.now()
44+
45+
console.log(`[${requestId}] 📝 CLIENT: Starting unit creation for "${unitName.trim()}"`)
46+
4147
const tempId = `temp-${Date.now()}`
4248
const tempUnit = { id: tempId, name: unitName.trim(), isOptimistic: true }
4349

4450
// Optimistic update - show immediately
4551
if (onCreatedOptimistic) {
4652
onCreatedOptimistic(tempUnit)
53+
console.log(`[${requestId}] ⚡ CLIENT: Optimistic UI update applied (+${Date.now() - startTime}ms)`)
4754
}
4855

4956
try {
57+
const serverCallStart = Date.now()
5058
const unit = await createUnitFn({
5159
data: {
5260
userId,
5361
organisationId,
5462
email,
5563
name: unitName.trim(),
64+
requestId, // Pass request ID to server
5665
},
5766
})
67+
const totalTime = Date.now() - startTime
68+
console.log(`[${requestId}] ✅ CLIENT: Unit created successfully (server: ${Date.now() - serverCallStart}ms, total: ${totalTime}ms)`)
5869
onCreated({ id: unit.id, name: unit.name })
5970
} catch (e: any) {
71+
const totalTime = Date.now() - startTime
72+
console.error(`[${requestId}] ❌ CLIENT: Unit creation failed after ${totalTime}ms:`, e?.message)
6073
setError(e?.message ?? 'Failed to create unit')
6174
if (onCreatedFailed) {
6275
onCreatedFailed()

‎ui/src/routes/tfe/$.tsx‎

Lines changed: 6 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -31,7 +31,9 @@ async function handler({ request }) {
3131
const response = await fetch(`${process.env.STATESMAN_BACKEND_URL}${url.pathname}${url.search}`, {
3232
method: request.method,
3333
headers: outgoingHeaders,
34-
body: request.method !== 'GET' && request.method !== 'HEAD' ? await request.blob() : undefined
34+
body: request.method !== 'GET' && request.method !== 'HEAD' ? request.body : undefined,
35+
// @ts-ignore - duplex is required for streaming but not in @types/node yet
36+
duplex: 'half',
3537
});
3638

3739
const headers = new Headers(response.headers);
@@ -157,7 +159,9 @@ async function handler({ request }) {
157159
const response = await fetch(`${process.env.STATESMAN_BACKEND_URL}${internalPath}${url.search}`, {
158160
method: request.method,
159161
headers: outgoingHeaders,
160-
body: request.method !== 'GET' && request.method !== 'HEAD' ? await request.blob() : undefined
162+
body: request.method !== 'GET' && request.method !== 'HEAD' ? request.body : undefined,
163+
// @ts-ignore - duplex is required for streaming but not in @types/node yet
164+
duplex: 'half',
161165
});
162166

163167
const proxyTime = Date.now() - startProxy;

0 commit comments

Comments
 (0)