| 1 | package cli |
| 2 | |
| 3 | import ( |
| 4 | "bufio" |
| 5 | "context" |
| 6 | "encoding/json" |
| 7 | "fmt" |
| 8 | "net/http" |
| 9 | "os" |
| 10 | "os/exec" |
| 11 | "strings" |
| 12 | "testing" |
| 13 | "time" |
| 14 | |
| 15 | "github.com/ipfs/kubo/test/cli/harness" |
| 16 | . "github.com/ipfs/kubo/test/cli/testutils" |
| 17 | "github.com/stretchr/testify/assert" |
| 18 | "github.com/stretchr/testify/require" |
| 19 | ) |
| 20 | |
| 21 | func TestLogLevel(t *testing.T) { |
| 22 | |
| 23 | t.Run("CLI", func(t *testing.T) { |
| 24 | t.Run("level '*' shows all subsystems", func(t *testing.T) { |
| 25 | t.Parallel() |
| 26 | node := harness.NewT(t).NewNode().Init().StartDaemon() |
| 27 | defer node.StopDaemon() |
| 28 | |
| 29 | expectedSubsystems := getExpectedSubsystems(t, node) |
| 30 | |
| 31 | res := node.IPFS("log", "level", "*") |
| 32 | assert.NoError(t, res.Err) |
| 33 | assert.Empty(t, res.Stderr.Lines()) |
| 34 | |
| 35 | actualSubsystems := parseCLIOutput(t, res.Stdout.String()) |
| 36 | |
| 37 | // Should show all subsystems plus the (default) entry |
| 38 | assert.GreaterOrEqual(t, len(actualSubsystems), len(expectedSubsystems)) |
| 39 | |
| 40 | validateAllSubsystemsPresentCLI(t, expectedSubsystems, actualSubsystems, "CLI output") |
| 41 | |
| 42 | // Should have the (default) entry |
| 43 | _, hasDefault := actualSubsystems["(default)"] |
| 44 | assert.True(t, hasDefault, "Should have '(default)' entry") |
| 45 | }) |
| 46 | |
| 47 | t.Run("level 'all' shows all subsystems (alias for '*')", func(t *testing.T) { |
| 48 | t.Parallel() |
| 49 | node := harness.NewT(t).NewNode().Init().StartDaemon() |
| 50 | defer node.StopDaemon() |
| 51 | |
| 52 | expectedSubsystems := getExpectedSubsystems(t, node) |
| 53 | |
| 54 | res := node.IPFS("log", "level", "all") |
| 55 | assert.NoError(t, res.Err) |
| 56 | assert.Empty(t, res.Stderr.Lines()) |
| 57 | |
| 58 | actualSubsystems := parseCLIOutput(t, res.Stdout.String()) |
| 59 | |
| 60 | // Should show all subsystems plus the (default) entry |
| 61 | assert.GreaterOrEqual(t, len(actualSubsystems), len(expectedSubsystems)) |
| 62 | |
| 63 | validateAllSubsystemsPresentCLI(t, expectedSubsystems, actualSubsystems, "CLI output") |
| 64 | |
| 65 | // Should have the (default) entry |
| 66 | _, hasDefault := actualSubsystems["(default)"] |
| 67 | assert.True(t, hasDefault, "Should have '(default)' entry") |
| 68 | }) |
| 69 | |
| 70 | t.Run("get level for specific subsystem", func(t *testing.T) { |
| 71 | t.Parallel() |
| 72 | node := harness.NewT(t).NewNode().Init().StartDaemon() |
| 73 | defer node.StopDaemon() |
| 74 | |
| 75 | node.IPFS("log", "level", "core", "debug") |
| 76 | res := node.IPFS("log", "level", "core") |
| 77 | assert.NoError(t, res.Err) |
| 78 | assert.Empty(t, res.Stderr.Lines()) |
| 79 | |
| 80 | output := res.Stdout.String() |
| 81 | lines := SplitLines(output) |
| 82 | |
| 83 | assert.Equal(t, 1, len(lines)) |
| 84 | |
| 85 | line := strings.TrimSpace(lines[0]) |
| 86 | assert.Equal(t, "debug", line) |
| 87 | }) |
| 88 | |
| 89 | t.Run("get level with no args returns default level", func(t *testing.T) { |
| 90 | t.Parallel() |
| 91 | node := harness.NewT(t).NewNode().Init().StartDaemon() |
| 92 | defer node.StopDaemon() |
| 93 | |
| 94 | res1 := node.IPFS("log", "level", "*", "fatal") |
| 95 | assert.NoError(t, res1.Err) |
| 96 | assert.Empty(t, res1.Stderr.Lines()) |
| 97 | |
| 98 | res := node.IPFS("log", "level") |
| 99 | assert.NoError(t, res.Err) |
| 100 | assert.Equal(t, 0, len(res.Stderr.Lines())) |
| 101 | |
| 102 | output := res.Stdout.String() |
| 103 | lines := SplitLines(output) |
| 104 | |
| 105 | assert.Equal(t, 1, len(lines)) |
| 106 | |
| 107 | line := strings.TrimSpace(lines[0]) |
| 108 | assert.Equal(t, "fatal", line) |
| 109 | }) |
| 110 | |
| 111 | t.Run("get level reflects runtime log level changes", func(t *testing.T) { |
| 112 | t.Parallel() |
| 113 | node := harness.NewT(t).NewNode().Init().StartDaemon("--offline") |
| 114 | defer node.StopDaemon() |
| 115 | |
| 116 | node.IPFS("log", "level", "core", "debug") |
| 117 | res := node.IPFS("log", "level", "core") |
| 118 | assert.NoError(t, res.Err) |
| 119 | |
| 120 | output := res.Stdout.String() |
| 121 | lines := SplitLines(output) |
| 122 | |
| 123 | assert.Equal(t, 1, len(lines)) |
| 124 | |
| 125 | line := strings.TrimSpace(lines[0]) |
| 126 | assert.Equal(t, "debug", line) |
| 127 | }) |
| 128 | |
| 129 | t.Run("get level with non-existent subsystem returns error", func(t *testing.T) { |
| 130 | t.Parallel() |
| 131 | node := harness.NewT(t).NewNode().Init().StartDaemon() |
| 132 | defer node.StopDaemon() |
| 133 | |
| 134 | res := node.RunIPFS("log", "level", "non-existent-subsystem") |
| 135 | assert.Error(t, res.Err) |
| 136 | assert.NotEqual(t, 0, len(res.Stderr.Lines())) |
| 137 | }) |
| 138 | |
| 139 | t.Run("set level to 'default' keyword", func(t *testing.T) { |
| 140 | t.Parallel() |
| 141 | node := harness.NewT(t).NewNode().Init().StartDaemon() |
| 142 | defer node.StopDaemon() |
| 143 | |
| 144 | // First set a specific subsystem to a different level |
| 145 | res1 := node.IPFS("log", "level", "core", "debug") |
| 146 | assert.NoError(t, res1.Err) |
| 147 | assert.Contains(t, res1.Stdout.String(), "Changed log level of 'core' to 'debug'") |
| 148 | |
| 149 | // Verify it was set to debug |
| 150 | res2 := node.IPFS("log", "level", "core") |
| 151 | assert.NoError(t, res2.Err) |
| 152 | assert.Equal(t, "debug", strings.TrimSpace(res2.Stdout.String())) |
| 153 | |
| 154 | // Get the current default level (should be 'error' since unchanged) |
| 155 | res3 := node.IPFS("log", "level") |
| 156 | assert.NoError(t, res3.Err) |
| 157 | defaultLevel := strings.TrimSpace(res3.Stdout.String()) |
| 158 | assert.Equal(t, "error", defaultLevel, "Default level should be 'error' when unchanged") |
| 159 | |
| 160 | // Now set the subsystem back to default |
| 161 | res4 := node.IPFS("log", "level", "core", "default") |
| 162 | assert.NoError(t, res4.Err) |
| 163 | assert.Contains(t, res4.Stdout.String(), "Changed log level of 'core' to") |
| 164 | |
| 165 | // Verify it's now at the default level (should be 'error') |
| 166 | res5 := node.IPFS("log", "level", "core") |
| 167 | assert.NoError(t, res5.Err) |
| 168 | assert.Equal(t, "error", strings.TrimSpace(res5.Stdout.String())) |
| 169 | }) |
| 170 | |
| 171 | t.Run("set all subsystems with 'all' changes default (alias for '*')", func(t *testing.T) { |
| 172 | t.Parallel() |
| 173 | node := harness.NewT(t).NewNode().Init().StartDaemon() |
| 174 | defer node.StopDaemon() |
| 175 | |
| 176 | // Initial state - default should be 'error' |
| 177 | res := node.IPFS("log", "level") |
| 178 | assert.NoError(t, res.Err) |
| 179 | assert.Equal(t, "error", strings.TrimSpace(res.Stdout.String())) |
| 180 | |
| 181 | // Set one subsystem to a different level |
| 182 | res = node.IPFS("log", "level", "core", "debug") |
| 183 | assert.NoError(t, res.Err) |
| 184 | |
| 185 | // Default should still be 'error' |
| 186 | res = node.IPFS("log", "level") |
| 187 | assert.NoError(t, res.Err) |
| 188 | assert.Equal(t, "error", strings.TrimSpace(res.Stdout.String())) |
| 189 | |
| 190 | // Now use 'all' to set everything to 'info' |
| 191 | res = node.IPFS("log", "level", "all", "info") |
| 192 | assert.NoError(t, res.Err) |
| 193 | assert.Contains(t, res.Stdout.String(), "Changed log level of '*' to 'info'") |
| 194 | |
| 195 | // Default should now be 'info' |
| 196 | res = node.IPFS("log", "level") |
| 197 | assert.NoError(t, res.Err) |
| 198 | assert.Equal(t, "info", strings.TrimSpace(res.Stdout.String())) |
| 199 | |
| 200 | // Core should also be 'info' (overwritten by 'all') |
| 201 | res = node.IPFS("log", "level", "core") |
| 202 | assert.NoError(t, res.Err) |
| 203 | assert.Equal(t, "info", strings.TrimSpace(res.Stdout.String())) |
| 204 | |
| 205 | // Any other subsystem should also be 'info' |
| 206 | res = node.IPFS("log", "level", "dht") |
| 207 | assert.NoError(t, res.Err) |
| 208 | assert.Equal(t, "info", strings.TrimSpace(res.Stdout.String())) |
| 209 | }) |
| 210 | |
| 211 | t.Run("set all subsystems with '*' changes default", func(t *testing.T) { |
| 212 | t.Parallel() |
| 213 | node := harness.NewT(t).NewNode().Init().StartDaemon() |
| 214 | defer node.StopDaemon() |
| 215 | |
| 216 | // Initial state - default should be 'error' |
| 217 | res := node.IPFS("log", "level") |
| 218 | assert.NoError(t, res.Err) |
| 219 | assert.Equal(t, "error", strings.TrimSpace(res.Stdout.String())) |
| 220 | |
| 221 | // Set one subsystem to a different level |
| 222 | res = node.IPFS("log", "level", "core", "debug") |
| 223 | assert.NoError(t, res.Err) |
| 224 | |
| 225 | // Default should still be 'error' |
| 226 | res = node.IPFS("log", "level") |
| 227 | assert.NoError(t, res.Err) |
| 228 | assert.Equal(t, "error", strings.TrimSpace(res.Stdout.String())) |
| 229 | |
| 230 | // Now use '*' to set everything to 'info' |
| 231 | res = node.IPFS("log", "level", "*", "info") |
| 232 | assert.NoError(t, res.Err) |
| 233 | assert.Contains(t, res.Stdout.String(), "Changed log level of '*' to 'info'") |
| 234 | |
| 235 | // Default should now be 'info' |
| 236 | res = node.IPFS("log", "level") |
| 237 | assert.NoError(t, res.Err) |
| 238 | assert.Equal(t, "info", strings.TrimSpace(res.Stdout.String())) |
| 239 | |
| 240 | // Core should also be 'info' (overwritten by '*') |
| 241 | res = node.IPFS("log", "level", "core") |
| 242 | assert.NoError(t, res.Err) |
| 243 | assert.Equal(t, "info", strings.TrimSpace(res.Stdout.String())) |
| 244 | |
| 245 | // Any other subsystem should also be 'info' |
| 246 | res = node.IPFS("log", "level", "dht") |
| 247 | assert.NoError(t, res.Err) |
| 248 | assert.Equal(t, "info", strings.TrimSpace(res.Stdout.String())) |
| 249 | }) |
| 250 | |
| 251 | t.Run("'all' in get mode shows (default) entry (alias for '*')", func(t *testing.T) { |
| 252 | t.Parallel() |
| 253 | node := harness.NewT(t).NewNode().Init().StartDaemon() |
| 254 | defer node.StopDaemon() |
| 255 | |
| 256 | // Get all levels with 'all' |
| 257 | res := node.IPFS("log", "level", "all") |
| 258 | assert.NoError(t, res.Err) |
| 259 | |
| 260 | output := res.Stdout.String() |
| 261 | |
| 262 | // Should contain "(default): error" entry |
| 263 | assert.Contains(t, output, "(default): error", "Should show default level with (default) key") |
| 264 | |
| 265 | // Should also contain various subsystems |
| 266 | assert.Contains(t, output, "core: error") |
| 267 | assert.Contains(t, output, "dht: error") |
| 268 | }) |
| 269 | |
| 270 | t.Run("'*' in get mode shows (default) entry", func(t *testing.T) { |
| 271 | t.Parallel() |
| 272 | node := harness.NewT(t).NewNode().Init().StartDaemon() |
| 273 | defer node.StopDaemon() |
| 274 | |
| 275 | // Get all levels with '*' |
| 276 | res := node.IPFS("log", "level", "*") |
| 277 | assert.NoError(t, res.Err) |
| 278 | |
| 279 | output := res.Stdout.String() |
| 280 | |
| 281 | // Should contain "(default): error" entry |
| 282 | assert.Contains(t, output, "(default): error", "Should show default level with (default) key") |
| 283 | |
| 284 | // Should also contain various subsystems |
| 285 | assert.Contains(t, output, "core: error") |
| 286 | assert.Contains(t, output, "dht: error") |
| 287 | }) |
| 288 | |
| 289 | t.Run("set all subsystems to 'default' using 'all' (alias for '*')", func(t *testing.T) { |
| 290 | t.Parallel() |
| 291 | node := harness.NewT(t).NewNode().Init().StartDaemon() |
| 292 | defer node.StopDaemon() |
| 293 | |
| 294 | // Get the original default level (just for reference, it should be "error") |
| 295 | res0 := node.IPFS("log", "level") |
| 296 | assert.NoError(t, res0.Err) |
| 297 | assert.Equal(t, "error", strings.TrimSpace(res0.Stdout.String())) |
| 298 | |
| 299 | // First set all subsystems to debug using 'all' |
| 300 | res1 := node.IPFS("log", "level", "all", "debug") |
| 301 | assert.NoError(t, res1.Err) |
| 302 | assert.Contains(t, res1.Stdout.String(), "Changed log level of '*' to 'debug'") |
| 303 | |
| 304 | // Verify a specific subsystem is at debug |
| 305 | res2 := node.IPFS("log", "level", "core") |
| 306 | assert.NoError(t, res2.Err) |
| 307 | assert.Equal(t, "debug", strings.TrimSpace(res2.Stdout.String())) |
| 308 | |
| 309 | // Verify the default level is now debug |
| 310 | res3 := node.IPFS("log", "level") |
| 311 | assert.NoError(t, res3.Err) |
| 312 | assert.Equal(t, "debug", strings.TrimSpace(res3.Stdout.String())) |
| 313 | |
| 314 | // Now set all subsystems back to default (which is now "debug") using 'all' |
| 315 | res4 := node.IPFS("log", "level", "all", "default") |
| 316 | assert.NoError(t, res4.Err) |
| 317 | assert.Contains(t, res4.Stdout.String(), "Changed log level of '*' to") |
| 318 | |
| 319 | // The subsystem should still be at debug (because that's what default is now) |
| 320 | res5 := node.IPFS("log", "level", "core") |
| 321 | assert.NoError(t, res5.Err) |
| 322 | assert.Equal(t, "debug", strings.TrimSpace(res5.Stdout.String())) |
| 323 | |
| 324 | // The behavior is correct: "default" uses the current default level, |
| 325 | // which was changed to "debug" when we set "all" to "debug" |
| 326 | }) |
| 327 | |
| 328 | t.Run("set all subsystems to 'default' keyword", func(t *testing.T) { |
| 329 | t.Parallel() |
| 330 | node := harness.NewT(t).NewNode().Init().StartDaemon() |
| 331 | defer node.StopDaemon() |
| 332 | |
| 333 | // Get the original default level (just for reference, it should be "error") |
| 334 | res0 := node.IPFS("log", "level") |
| 335 | assert.NoError(t, res0.Err) |
| 336 | // originalDefault := strings.TrimSpace(res0.Stdout.String()) |
| 337 | assert.Equal(t, "error", strings.TrimSpace(res0.Stdout.String())) |
| 338 | |
| 339 | // First set all subsystems to debug |
| 340 | res1 := node.IPFS("log", "level", "*", "debug") |
| 341 | assert.NoError(t, res1.Err) |
| 342 | assert.Contains(t, res1.Stdout.String(), "Changed log level of '*' to 'debug'") |
| 343 | |
| 344 | // Verify a specific subsystem is at debug |
| 345 | res2 := node.IPFS("log", "level", "core") |
| 346 | assert.NoError(t, res2.Err) |
| 347 | assert.Equal(t, "debug", strings.TrimSpace(res2.Stdout.String())) |
| 348 | |
| 349 | // Verify the default level is now debug |
| 350 | res3 := node.IPFS("log", "level") |
| 351 | assert.NoError(t, res3.Err) |
| 352 | assert.Equal(t, "debug", strings.TrimSpace(res3.Stdout.String())) |
| 353 | |
| 354 | // Now set all subsystems back to default (which is now "debug") |
| 355 | res4 := node.IPFS("log", "level", "*", "default") |
| 356 | assert.NoError(t, res4.Err) |
| 357 | assert.Contains(t, res4.Stdout.String(), "Changed log level of '*' to") |
| 358 | |
| 359 | // The subsystem should still be at debug (because that's what default is now) |
| 360 | res5 := node.IPFS("log", "level", "core") |
| 361 | assert.NoError(t, res5.Err) |
| 362 | assert.Equal(t, "debug", strings.TrimSpace(res5.Stdout.String())) |
| 363 | |
| 364 | // The behavior is correct: "default" uses the current default level, |
| 365 | // which was changed to "debug" when we set "*" to "debug" |
| 366 | }) |
| 367 | |
| 368 | t.Run("shell escaping variants for '*' wildcard", func(t *testing.T) { |
| 369 | t.Parallel() |
| 370 | h := harness.NewT(t) |
| 371 | node := h.NewNode().Init().StartDaemon() |
| 372 | defer node.StopDaemon() |
| 373 | |
| 374 | // Test different shell escaping methods work for '*' |
| 375 | // This tests the behavior documented in help text: '*' or "*" or \* |
| 376 | |
| 377 | // Test 1: Single quotes '*' (should work) |
| 378 | cmd1 := fmt.Sprintf("IPFS_PATH='%s' %s --api='%s' log level '*' info", |
| 379 | node.Dir, node.IPFSBin, node.APIAddr()) |
| 380 | res1 := h.Sh(cmd1) |
| 381 | assert.NoError(t, res1.Err) |
| 382 | assert.Contains(t, res1.Stdout.String(), "Changed log level of '*' to 'info'") |
| 383 | |
| 384 | // Test 2: Double quotes "*" (should work) |
| 385 | cmd2 := fmt.Sprintf("IPFS_PATH='%s' %s --api='%s' log level \"*\" debug", |
| 386 | node.Dir, node.IPFSBin, node.APIAddr()) |
| 387 | res2 := h.Sh(cmd2) |
| 388 | assert.NoError(t, res2.Err) |
| 389 | assert.Contains(t, res2.Stdout.String(), "Changed log level of '*' to 'debug'") |
| 390 | |
| 391 | // Test 3: Backslash escape \* (should work) |
| 392 | cmd3 := fmt.Sprintf("IPFS_PATH='%s' %s --api='%s' log level \\* warn", |
| 393 | node.Dir, node.IPFSBin, node.APIAddr()) |
| 394 | res3 := h.Sh(cmd3) |
| 395 | assert.NoError(t, res3.Err) |
| 396 | assert.Contains(t, res3.Stdout.String(), "Changed log level of '*' to 'warn'") |
| 397 | |
| 398 | // Test 4: Verify the final state - should show 'warn' as default |
| 399 | res4 := node.IPFS("log", "level") |
| 400 | assert.NoError(t, res4.Err) |
| 401 | assert.Equal(t, "warn", strings.TrimSpace(res4.Stdout.String())) |
| 402 | |
| 403 | // Test 5: Get all levels using escaped '*' to verify it shows all subsystems |
| 404 | cmd5 := fmt.Sprintf("IPFS_PATH='%s' %s --api='%s' log level \\*", |
| 405 | node.Dir, node.IPFSBin, node.APIAddr()) |
| 406 | res5 := h.Sh(cmd5) |
| 407 | assert.NoError(t, res5.Err) |
| 408 | output := res5.Stdout.String() |
| 409 | assert.Contains(t, output, "(default): warn", "Should show updated default level") |
| 410 | assert.Contains(t, output, "core: warn", "Should show core subsystem at warn level") |
| 411 | }) |
| 412 | }) |
| 413 | |
| 414 | t.Run("HTTP RPC", func(t *testing.T) { |
| 415 | t.Run("get default level returns JSON", func(t *testing.T) { |
| 416 | t.Parallel() |
| 417 | node := harness.NewT(t).NewNode().Init().StartDaemon() |
| 418 | defer node.StopDaemon() |
| 419 | |
| 420 | // Make HTTP request to get default log level |
| 421 | resp, err := http.Post(node.APIURL()+"/api/v0/log/level", "", nil) |
| 422 | require.NoError(t, err) |
| 423 | defer resp.Body.Close() |
| 424 | |
| 425 | // Parse JSON response |
| 426 | var result map[string]any |
| 427 | err = json.NewDecoder(resp.Body).Decode(&result) |
| 428 | require.NoError(t, err) |
| 429 | |
| 430 | // Check that we have the Levels field |
| 431 | levels, ok := result["Levels"].(map[string]any) |
| 432 | require.True(t, ok, "Response should have 'Levels' field") |
| 433 | |
| 434 | // Should have exactly one entry for the default level |
| 435 | assert.Equal(t, 1, len(levels)) |
| 436 | |
| 437 | // The default level should be present |
| 438 | defaultLevel, ok := levels[""] |
| 439 | require.True(t, ok, "Should have empty string key for default level") |
| 440 | assert.Equal(t, "error", defaultLevel, "Default level should be 'error'") |
| 441 | }) |
| 442 | |
| 443 | t.Run("get all levels using 'all' returns JSON (alias for '*')", func(t *testing.T) { |
| 444 | t.Parallel() |
| 445 | node := harness.NewT(t).NewNode().Init().StartDaemon() |
| 446 | defer node.StopDaemon() |
| 447 | |
| 448 | expectedSubsystems := getExpectedSubsystems(t, node) |
| 449 | |
| 450 | // Make HTTP request to get all log levels using 'all' |
| 451 | resp, err := http.Post(node.APIURL()+"/api/v0/log/level?arg=all", "", nil) |
| 452 | require.NoError(t, err) |
| 453 | defer resp.Body.Close() |
| 454 | |
| 455 | levels := parseHTTPResponse(t, resp) |
| 456 | validateAllSubsystemsPresent(t, expectedSubsystems, levels, "JSON response") |
| 457 | |
| 458 | // Should have the (default) entry |
| 459 | defaultLevel, ok := levels["(default)"] |
| 460 | require.True(t, ok, "Should have '(default)' key") |
| 461 | assert.Equal(t, "error", defaultLevel, "Default level should be 'error'") |
| 462 | }) |
| 463 | |
| 464 | t.Run("get all levels returns JSON", func(t *testing.T) { |
| 465 | t.Parallel() |
| 466 | node := harness.NewT(t).NewNode().Init().StartDaemon() |
| 467 | defer node.StopDaemon() |
| 468 | |
| 469 | expectedSubsystems := getExpectedSubsystems(t, node) |
| 470 | |
| 471 | // Make HTTP request to get all log levels |
| 472 | resp, err := http.Post(node.APIURL()+"/api/v0/log/level?arg=*", "", nil) |
| 473 | require.NoError(t, err) |
| 474 | defer resp.Body.Close() |
| 475 | |
| 476 | levels := parseHTTPResponse(t, resp) |
| 477 | validateAllSubsystemsPresent(t, expectedSubsystems, levels, "JSON response") |
| 478 | |
| 479 | // Should have the (default) entry |
| 480 | defaultLevel, ok := levels["(default)"] |
| 481 | require.True(t, ok, "Should have '(default)' key") |
| 482 | assert.Equal(t, "error", defaultLevel, "Default level should be 'error'") |
| 483 | }) |
| 484 | |
| 485 | t.Run("get specific subsystem level returns JSON", func(t *testing.T) { |
| 486 | t.Parallel() |
| 487 | node := harness.NewT(t).NewNode().Init().StartDaemon() |
| 488 | defer node.StopDaemon() |
| 489 | |
| 490 | // First set a specific level for a subsystem |
| 491 | resp, err := http.Post(node.APIURL()+"/api/v0/log/level?arg=core&arg=debug", "", nil) |
| 492 | require.NoError(t, err) |
| 493 | resp.Body.Close() |
| 494 | |
| 495 | // Now get the level for that subsystem |
| 496 | resp, err = http.Post(node.APIURL()+"/api/v0/log/level?arg=core", "", nil) |
| 497 | require.NoError(t, err) |
| 498 | defer resp.Body.Close() |
| 499 | |
| 500 | // Parse JSON response |
| 501 | var result map[string]any |
| 502 | err = json.NewDecoder(resp.Body).Decode(&result) |
| 503 | require.NoError(t, err) |
| 504 | |
| 505 | // Check that we have the Levels field |
| 506 | levels, ok := result["Levels"].(map[string]any) |
| 507 | require.True(t, ok, "Response should have 'Levels' field") |
| 508 | |
| 509 | // Should have exactly one entry |
| 510 | assert.Equal(t, 1, len(levels)) |
| 511 | |
| 512 | // Check the level for 'core' subsystem |
| 513 | coreLevel, ok := levels["core"] |
| 514 | require.True(t, ok, "Should have 'core' key") |
| 515 | assert.Equal(t, "debug", coreLevel, "Core level should be 'debug'") |
| 516 | }) |
| 517 | |
| 518 | t.Run("set level using 'all' returns JSON message (alias for '*')", func(t *testing.T) { |
| 519 | t.Parallel() |
| 520 | node := harness.NewT(t).NewNode().Init().StartDaemon() |
| 521 | defer node.StopDaemon() |
| 522 | |
| 523 | // Set a log level using 'all' |
| 524 | resp, err := http.Post(node.APIURL()+"/api/v0/log/level?arg=all&arg=info", "", nil) |
| 525 | require.NoError(t, err) |
| 526 | defer resp.Body.Close() |
| 527 | |
| 528 | // Parse JSON response |
| 529 | var result map[string]any |
| 530 | err = json.NewDecoder(resp.Body).Decode(&result) |
| 531 | require.NoError(t, err) |
| 532 | |
| 533 | // Check that we have the Message field |
| 534 | message, ok := result["Message"].(string) |
| 535 | require.True(t, ok, "Response should have 'Message' field") |
| 536 | |
| 537 | // Check the message content (should show '*' in message even when 'all' was used) |
| 538 | assert.Contains(t, message, "Changed log level of '*' to 'info'") |
| 539 | }) |
| 540 | |
| 541 | t.Run("set level returns JSON message", func(t *testing.T) { |
| 542 | t.Parallel() |
| 543 | node := harness.NewT(t).NewNode().Init().StartDaemon() |
| 544 | defer node.StopDaemon() |
| 545 | |
| 546 | // Set a log level |
| 547 | resp, err := http.Post(node.APIURL()+"/api/v0/log/level?arg=core&arg=info", "", nil) |
| 548 | require.NoError(t, err) |
| 549 | defer resp.Body.Close() |
| 550 | |
| 551 | // Parse JSON response |
| 552 | var result map[string]any |
| 553 | err = json.NewDecoder(resp.Body).Decode(&result) |
| 554 | require.NoError(t, err) |
| 555 | |
| 556 | // Check that we have the Message field |
| 557 | message, ok := result["Message"].(string) |
| 558 | require.True(t, ok, "Response should have 'Message' field") |
| 559 | |
| 560 | // Check the message content |
| 561 | assert.Contains(t, message, "Changed log level of 'core' to 'info'") |
| 562 | }) |
| 563 | |
| 564 | t.Run("set level to 'default' keyword", func(t *testing.T) { |
| 565 | t.Parallel() |
| 566 | node := harness.NewT(t).NewNode().Init().StartDaemon() |
| 567 | defer node.StopDaemon() |
| 568 | |
| 569 | // First set a subsystem to debug |
| 570 | resp, err := http.Post(node.APIURL()+"/api/v0/log/level?arg=core&arg=debug", "", nil) |
| 571 | require.NoError(t, err) |
| 572 | resp.Body.Close() |
| 573 | |
| 574 | // Now set it back to default |
| 575 | resp, err = http.Post(node.APIURL()+"/api/v0/log/level?arg=core&arg=default", "", nil) |
| 576 | require.NoError(t, err) |
| 577 | defer resp.Body.Close() |
| 578 | |
| 579 | // Parse JSON response |
| 580 | var result map[string]any |
| 581 | err = json.NewDecoder(resp.Body).Decode(&result) |
| 582 | require.NoError(t, err) |
| 583 | |
| 584 | // Check that we have the Message field |
| 585 | message, ok := result["Message"].(string) |
| 586 | require.True(t, ok, "Response should have 'Message' field") |
| 587 | |
| 588 | // The message should indicate the change |
| 589 | assert.True(t, strings.Contains(message, "Changed log level of 'core' to"), |
| 590 | "Message should indicate level change") |
| 591 | |
| 592 | // Verify the level is back to error (default) |
| 593 | resp, err = http.Post(node.APIURL()+"/api/v0/log/level?arg=core", "", nil) |
| 594 | require.NoError(t, err) |
| 595 | defer resp.Body.Close() |
| 596 | |
| 597 | var getResult map[string]any |
| 598 | err = json.NewDecoder(resp.Body).Decode(&getResult) |
| 599 | require.NoError(t, err) |
| 600 | |
| 601 | levels, _ := getResult["Levels"].(map[string]any) |
| 602 | coreLevel, _ := levels["core"].(string) |
| 603 | assert.Equal(t, "error", coreLevel, "Core level should be back to 'error' (default)") |
| 604 | }) |
| 605 | }) |
| 606 | |
| 607 | // Constants for slog interop tests |
| 608 | const ( |
| 609 | slogTestLogTailTimeout = 10 * time.Second |
| 610 | slogTestLogWaitTimeout = 5 * time.Second |
| 611 | slogTestLogStartupDelay = 1 * time.Second // Wait for log tail to start |
| 612 | slogTestSubsystemCmdsHTTP = "cmds/http" // Native go-log subsystem |
| 613 | slogTestSubsystemNetIdentify = "net/identify" // go-libp2p slog subsystem |
| 614 | ) |
| 615 | |
| 616 | // logMatch represents a matched log entry for slog interop tests |
| 617 | type logMatch struct { |
| 618 | subsystem string |
| 619 | line string |
| 620 | } |
| 621 | |
| 622 | // startLogMonitoring starts ipfs log tail and returns command and channel for matched logs. |
| 623 | startLogMonitoring := func(t *testing.T, node *harness.Node) (*exec.Cmd, chan logMatch) { |
| 624 | t.Helper() |
| 625 | |
| 626 | ctx, cancel := context.WithTimeout(context.Background(), slogTestLogTailTimeout) |
| 627 | t.Cleanup(cancel) |
| 628 | |
| 629 | cmd := exec.CommandContext(ctx, node.IPFSBin, "log", "tail") |
| 630 | cmd.Env = append([]string(nil), os.Environ()...) |
| 631 | for k, v := range node.Runner.Env { |
| 632 | cmd.Env = append(cmd.Env, fmt.Sprintf("%s=%s", k, v)) |
| 633 | } |
| 634 | cmd.Dir = node.Runner.Dir |
| 635 | |
| 636 | stdout, err := cmd.StdoutPipe() |
| 637 | require.NoError(t, err) |
| 638 | require.NoError(t, cmd.Start()) |
| 639 | |
| 640 | matches := make(chan logMatch, 10) |
| 641 | |
| 642 | go func() { |
| 643 | scanner := bufio.NewScanner(stdout) |
| 644 | for scanner.Scan() { |
| 645 | line := scanner.Text() |
| 646 | // Check for actual logger field in JSON, not just substring match |
| 647 | if strings.Contains(line, `"logger":"cmds/http"`) { |
| 648 | matches <- logMatch{slogTestSubsystemCmdsHTTP, line} |
| 649 | } |
| 650 | if strings.Contains(line, `"logger":"net/identify"`) { |
| 651 | matches <- logMatch{slogTestSubsystemNetIdentify, line} |
| 652 | } |
| 653 | } |
| 654 | }() |
| 655 | |
| 656 | return cmd, matches |
| 657 | } |
| 658 | |
| 659 | // waitForBothSubsystems waits for both native go-log and slog subsystems to appear in logs. |
| 660 | waitForBothSubsystems := func(t *testing.T, matches chan logMatch, timeout time.Duration) { |
| 661 | t.Helper() |
| 662 | |
| 663 | seen := make(map[string]struct{}) |
| 664 | deadline := time.After(timeout) |
| 665 | |
| 666 | for len(seen) < 2 { |
| 667 | select { |
| 668 | case match := <-matches: |
| 669 | if _, exists := seen[match.subsystem]; !exists { |
| 670 | t.Logf("Found %s log", match.subsystem) |
| 671 | seen[match.subsystem] = struct{}{} |
| 672 | } |
| 673 | case <-deadline: |
| 674 | t.Fatalf("Timeout waiting for logs. Seen: %v", seen) |
| 675 | } |
| 676 | } |
| 677 | |
| 678 | assert.Contains(t, seen, slogTestSubsystemCmdsHTTP, "should see cmds/http (native go-log)") |
| 679 | assert.Contains(t, seen, slogTestSubsystemNetIdentify, "should see net/identify (slog from go-libp2p)") |
| 680 | } |
| 681 | |
| 682 | // triggerIdentifyProtocol connects node1 to node2, triggering net/identify logs. |
| 683 | triggerIdentifyProtocol := func(t *testing.T, node1, node2 *harness.Node) { |
| 684 | t.Helper() |
| 685 | |
| 686 | // Get node2's peer ID and address |
| 687 | node2ID := node2.PeerID().String() |
| 688 | addrsRes := node2.IPFS("id", "-f", "<addrs>") |
| 689 | require.NoError(t, addrsRes.Err) |
| 690 | |
| 691 | addrs := strings.Split(strings.TrimSpace(addrsRes.Stdout.String()), "\n") |
| 692 | require.NotEmpty(t, addrs, "node2 should have at least one address") |
| 693 | |
| 694 | // Connect node1 to node2 |
| 695 | multiaddr := fmt.Sprintf("%s/p2p/%s", addrs[0], node2ID) |
| 696 | res := node1.IPFS("swarm", "connect", multiaddr) |
| 697 | require.NoError(t, res.Err) |
| 698 | } |
| 699 | |
| 700 | // verifySlogInterop verifies that both native go-log and slog from go-libp2p |
| 701 | // appear in ipfs log tail with correct formatting and level control. |
| 702 | verifySlogInterop := func(t *testing.T, node1, node2 *harness.Node) { |
| 703 | t.Helper() |
| 704 | |
| 705 | cmd, matches := startLogMonitoring(t, node1) |
| 706 | defer func() { |
| 707 | _ = cmd.Process.Kill() |
| 708 | }() |
| 709 | |
| 710 | time.Sleep(slogTestLogStartupDelay) |
| 711 | |
| 712 | // Trigger cmds/http (native go-log) |
| 713 | node1.IPFS("version") |
| 714 | |
| 715 | // Trigger net/identify (slog from go-libp2p) |
| 716 | triggerIdentifyProtocol(t, node1, node2) |
| 717 | |
| 718 | waitForBothSubsystems(t, matches, slogTestLogWaitTimeout) |
| 719 | } |
| 720 | |
| 721 | // This test verifies that go-log's slog bridge works with go-libp2p's gologshim |
| 722 | // when log levels are set via GOLOG_LOG_LEVEL environment variable. |
| 723 | // It tests both native go-log loggers (cmds/http) and slog-based loggers from |
| 724 | // go-libp2p (net/identify), ensuring both types appear in `ipfs log tail`. |
| 725 | t.Run("slog interop via env var", func(t *testing.T) { |
| 726 | t.Parallel() |
| 727 | h := harness.NewT(t) |
| 728 | |
| 729 | node1 := h.NewNode().Init() |
| 730 | node1.Runner.Env["GOLOG_LOG_LEVEL"] = "error,cmds/http=debug,net/identify=debug" |
| 731 | node1.StartDaemon() |
| 732 | defer node1.StopDaemon() |
| 733 | |
| 734 | node2 := h.NewNode().Init().StartDaemon() |
| 735 | defer node2.StopDaemon() |
| 736 | |
| 737 | verifySlogInterop(t, node1, node2) |
| 738 | }) |
| 739 | |
| 740 | // This test verifies that go-log's slog bridge works with go-libp2p's gologshim |
| 741 | // when log levels are set dynamically via `ipfs log level` CLI commands. |
| 742 | // It tests the key feature that SetLogLevel auto-creates level entries for subsystems |
| 743 | // that don't exist yet, enabling `ipfs log level net/identify debug` to work even |
| 744 | // before the net/identify logger is created. This is critical for slog interop. |
| 745 | t.Run("slog interop via CLI", func(t *testing.T) { |
| 746 | t.Parallel() |
| 747 | h := harness.NewT(t) |
| 748 | |
| 749 | node1 := h.NewNode().Init().StartDaemon() |
| 750 | defer node1.StopDaemon() |
| 751 | |
| 752 | node2 := h.NewNode().Init().StartDaemon() |
| 753 | defer node2.StopDaemon() |
| 754 | |
| 755 | // Set levels via CLI for both subsystems BEFORE triggering events |
| 756 | res := node1.IPFS("log", "level", slogTestSubsystemCmdsHTTP, "debug") |
| 757 | require.NoError(t, res.Err) |
| 758 | |
| 759 | res = node1.IPFS("log", "level", slogTestSubsystemNetIdentify, "debug") |
| 760 | require.NoError(t, res.Err) // Auto-creates level entry for slog subsystem |
| 761 | |
| 762 | verifySlogInterop(t, node1, node2) |
| 763 | }) |
| 764 | |
| 765 | } |
| 766 | |
| 767 | func getExpectedSubsystems(t *testing.T, node *harness.Node) []string { |
| 768 | t.Helper() |
| 769 | lsRes := node.IPFS("log", "ls") |
| 770 | require.NoError(t, lsRes.Err) |
| 771 | expectedSubsystems := SplitLines(lsRes.Stdout.String()) |
| 772 | assert.Greater(t, len(expectedSubsystems), 10, "Should have many subsystems") |
| 773 | return expectedSubsystems |
| 774 | } |
| 775 | |
| 776 | func parseCLIOutput(t *testing.T, output string) map[string]string { |
| 777 | t.Helper() |
| 778 | lines := SplitLines(output) |
| 779 | actualSubsystems := make(map[string]string) |
| 780 | for _, line := range lines { |
| 781 | if strings.TrimSpace(line) == "" { |
| 782 | continue |
| 783 | } |
| 784 | parts := strings.Split(line, ": ") |
| 785 | assert.Equal(t, 2, len(parts), "Line should have format 'subsystem: level', got: %s", line) |
| 786 | assert.NotEmpty(t, parts[0], "Subsystem should not be empty") |
| 787 | assert.NotEmpty(t, parts[1], "Level should not be empty") |
| 788 | actualSubsystems[parts[0]] = parts[1] |
| 789 | } |
| 790 | return actualSubsystems |
| 791 | } |
| 792 | |
| 793 | func parseHTTPResponse(t *testing.T, resp *http.Response) map[string]any { |
| 794 | t.Helper() |
| 795 | var result map[string]any |
| 796 | err := json.NewDecoder(resp.Body).Decode(&result) |
| 797 | require.NoError(t, err) |
| 798 | levels, ok := result["Levels"].(map[string]any) |
| 799 | require.True(t, ok, "Response should have 'Levels' field") |
| 800 | assert.Greater(t, len(levels), 10, "Should have many subsystems") |
| 801 | return levels |
| 802 | } |
| 803 | |
| 804 | func validateAllSubsystemsPresent(t *testing.T, expectedSubsystems []string, actualLevels map[string]any, context string) { |
| 805 | t.Helper() |
| 806 | for _, expectedSub := range expectedSubsystems { |
| 807 | expectedSub = strings.TrimSpace(expectedSub) |
| 808 | if expectedSub == "" { |
| 809 | continue |
| 810 | } |
| 811 | _, found := actualLevels[expectedSub] |
| 812 | assert.True(t, found, "Expected subsystem '%s' should be present in %s", expectedSub, context) |
| 813 | } |
| 814 | } |
| 815 | |
| 816 | func validateAllSubsystemsPresentCLI(t *testing.T, expectedSubsystems []string, actualLevels map[string]string, context string) { |
| 817 | t.Helper() |
| 818 | for _, expectedSub := range expectedSubsystems { |
| 819 | expectedSub = strings.TrimSpace(expectedSub) |
| 820 | if expectedSub == "" { |
| 821 | continue |
| 822 | } |
| 823 | _, found := actualLevels[expectedSub] |
| 824 | assert.True(t, found, "Expected subsystem '%s' should be present in %s", expectedSub, context) |
| 825 | } |
| 826 | } |