fix(profiler): refine regular expression for parsing backoff duration in E2E tests (#5229)

Author: nolanmar511

profiler/proftest/proftest.go

@@ -47,7 +47,7 @@ var (
 
 	// "ms" must be specified before "m" in the regexp, to ensure "ms" is fully
 	// matched.
-	backoffTimeRE = regexp.MustCompile(`(\d+(\.\d+)?(ms|h|m|s|us))+`)
+	backoffTimeRE = regexp.MustCompile(`(?:^|\W)((\d+(\.\d+)?(ms|h|m|s|us))+)(?:$|\W)`)
 )
 
 // BaseStartupTmpl is the common part of the startup script that
@@ -454,10 +454,11 @@ func parseLogTime(line string) (time.Time, error) {
 // parseBackoffDuration returns the backoff duration associated with a logged
 // line, or an error if the line does not contain a valid backoff duration.
 func parseBackoffDuration(line string) (time.Duration, error) {
-	backoffTimeStr := backoffTimeRE.FindString(line)
-	if backoffTimeStr == "" {
+	backoffTimeMatch := backoffTimeRE.FindStringSubmatch(line)
+	if len(backoffTimeMatch) < 2 || backoffTimeMatch[1] == "" {
 		return 0, fmt.Errorf("log for server-specified backoff %q does not include a backoff time", line)
 	}
+	backoffTimeStr := backoffTimeMatch[1]
 	backoff, err := time.ParseDuration(backoffTimeStr)
 	if err != nil {
 		return 0, fmt.Errorf("failed to parse backoff duration %q", backoffTimeStr)

profiler/proftest/proftest_test.go

@@ -120,8 +120,24 @@ func TestParseBackoffDuration(t *testing.T) {
 		wantErr        bool
 	}{
 		{
-			desc:           "a valid backoff duration is parsed correctly",
-			line:           "Fri May 15 22:05:01 UTC 2020: benchmark 0: failed to create profile, will retry: rpc error: code = Aborted desc = generic::aborted: action throttled, backoff for 32m0s",
+			desc:           "a valid backoff duration is parsed correctly when at the end of the message",
+			line:           "Fri May 15 22:05:01 UTC 2020: benchmark 0: action throttled, backoff for 32m0s",
+			wantBackoffDur: 32 * time.Minute,
+		},
+		{
+			desc:           "a valid backoff duration is parsed correctly when at the end of a message ending with a period",
+			line:           "Fri May 15 22:05:01 UTC 2020: benchmark 0: failed to create profile, will retry: rpc error: code = Aborted desc = generic::aborted: action throttled, backoff for 32m0s.",
+			wantBackoffDur: 32 * time.Minute,
+		},
+		{
+			desc:           "a valid backoff duration in a structured log statement is parsed correctly",
+			line:           `Mon Dec 20 20:21:40 UTC 2021: benchmark 39: {"timestamp":"2021-12-20T20:21:39.973Z","severity":"DEBUG","logging.googleapis.com/insertId":"..........K231soqV4EIcG8w42yR2.3","message":"Must wait 35m to create profile: Error: generic::aborted: action throttled, backoff for 35m0s","logName":"projects/{{projectId}}/logs/%40google-cloud%2Fprofiler","resource":{"type":"gae_app","labels":{"module_id":"profiler-backoff-test-node12-2021-12-20-12-18-47-077307-0800","zone":"us-east4-b"}}}`,
+			wantBackoffDur: 35 * time.Minute,
+		},
+
+		{
+			desc:           "a valid backoff duration is parsed correctly when in the middle of the message",
+			line:           "Fri May 15 22:05:01 UTC 2020: benchmark 0: failed to create profile, will retry: rpc error: code = Aborted desc = generic::aborted: action throttled, backoff for 32m0s ... more information",
 			wantBackoffDur: 32 * time.Minute,
 		},
 		{
@@ -139,6 +155,11 @@ func TestParseBackoffDuration(t *testing.T) {
 			line:           "Fri May 15 22:05:01 UTC 2020: benchmark 0: failed to create profile, will retry: rpc error: code = Aborted desc = generic::aborted: action throttled, backoff for 1h1m1s1ms1us",
 			wantBackoffDur: time.Hour + time.Minute + time.Second + time.Millisecond + time.Microsecond,
 		},
+		{
+			desc:           "a backoff duration at the start of the message is parsed correctly",
+			line:           "1h1m1s1ms",
+			wantBackoffDur: time.Hour + time.Minute + time.Second + time.Millisecond,
+		},
 	} {
 		t.Run(tc.desc, func(t *testing.T) {
 			backoffDur, err := parseBackoffDuration(tc.line)