podman

1
#!/usr/bin/env bats   -*- bats -*-
2
#
3
# Basic tests for podman logs
4
#
5

6
load helpers
7

8
@test "podman logs - basic test" {
9
    rand_string=$(random_string 40)
10

11
    run_podman create $IMAGE echo $rand_string
12
    cid="$output"
13

14
    run_podman logs $cid
15
    is "$output" ""  "logs on created container: empty"
16

17
    run_podman start --attach --interactive $cid
18
    is "$output" "$rand_string" "output from podman-start on created ctr"
19
    is "$output" "$rand_string" "logs of started container"
20

21
    run_podman logs $cid
22
    is "$output" "$rand_string" "output from podman-logs after container is run"
23

24
    # test --since with Unix timestamps
25
    run_podman logs --since 1000 $cid
26

27
    # test --until with Unix timestamps
28
    run_podman logs --until 1000 $cid
29

30
    run_podman rm $cid
31
}
32

33
function _log_test_tail() {
34
    local driver=$1
35

36
    run_podman run -d --log-driver=$driver $IMAGE sh -c "echo test1; echo test2"
37
    cid="$output"
38

39
    run_podman wait $cid
40
    run_podman logs --tail 1 --timestamps $cid
41
    log1="$output"
42
    assert "$log1" =~ "^[0-9-]+T[0-9:.]+([\+-][0-9:]+|Z) test2" \
43
           "logs should only show last line"
44

45
    # Sigh. I hate doing this, but podman-remote --timestamp only has 1-second
46
    # resolution (regular podman has sub-second). For the timestamps-differ
47
    # check below, we need to force a different second.
48
    if is_remote; then
49
        sleep 2
50
    fi
51

52
    run_podman restart $cid
53
    run_podman wait $cid
54

55
    run_podman logs -t --tail 1 $cid
56
    log2="$output"
57
    assert "$log2" =~ "^[0-9-]+T[0-9:.]+([\+-][0-9:]+|Z) test2" \
58
           "logs, after restart, shows only last line"
59

60
    assert "$log2" != "$log1" "log timestamps should differ"
61

62
    run_podman rm $cid
63
}
64

65
@test "podman logs - tail test, k8s-file" {
66
    _log_test_tail k8s-file
67
}
68

69
@test "podman logs - tail test, journald" {
70
    # We can't use journald on RHEL as rootless: rhbz#1895105
71
    skip_if_journald_unavailable
72

73
    _log_test_tail journald
74
}
75

76
function _additional_events_backend() {
77
    local driver=$1
78
    # Since PR#10431, 'logs -f' with journald driver is only supported with journald events backend.
79
    if [[ $driver = "journald" ]]; then
80
        run_podman info --format '{{.Host.EventLogger}}' >/dev/null
81
        if [[ $output != "journald" ]]; then
82
            echo "--events-backend journald"
83
        fi
84
    fi
85
}
86

87
function _log_test_multi() {
88
    local driver=$1
89

90
    skip_if_remote "logs does not support multiple containers when run remotely"
91

92
    # Under k8s file, 'podman logs' returns just the facts, Ma'am.
93
    # Under journald, there may be other cruft (e.g. container removals)
94
    local etc=
95
    if [[ $driver =~ journal ]]; then
96
        etc='.*'
97
    fi
98

99
    local events_backend=$(_additional_events_backend $driver)
100

101
    # Simple helper to make the container starts, below, easier to read
102
    local -a cid
103
    doit() {
104
        run_podman ${events_backend} run --log-driver=$driver --rm -d --name "$1" $IMAGE sh -c "$2";
105
        cid+=($(echo "${output:0:12}"))
106
    }
107

108
    # Not really a guarantee that we'll get a-b-c-d in order, but it's
109
    # the best we can do. The trailing 'sleep' in each container
110
    # minimizes the chance of a race condition in which the container
111
    # is removed before 'podman logs' has a chance to wake up and read
112
    # the final output.
113
    doit c1         "echo a;sleep 10;echo d;sleep 3"
114
    doit c2 "sleep 1;echo b;sleep  2;echo c;sleep 3"
115

116
    run_podman ${events_backend} logs -f c1 c2
117
    assert "$output" =~ \
118
       "${cid[0]} a$etc
119
${cid[1]} b$etc
120
${cid[1]} c$etc
121
${cid[0]} d"   "Sequential output from logs"
122
}
123

124
@test "podman logs - multi k8s-file" {
125
    _log_test_multi k8s-file
126
}
127

128
@test "podman logs - multi journald" {
129
    # We can't use journald on RHEL as rootless: rhbz#1895105
130
    skip_if_journald_unavailable
131

132
    _log_test_multi journald
133
}
134

135
function _log_test_restarted() {
136
    local driver=$1
137
    local events_backend=$(_additional_events_backend $driver)
138
    if [[ -n "${events_backend}" ]]; then
139
        skip_if_remote "remote does not support --events-backend"
140
    fi
141
    run_podman run --log-driver=$driver ${events_backend} --name logtest $IMAGE sh -c 'start=0; if test -s log; then start=`tail -n 1 log`; fi; seq `expr $start + 1` `expr $start + 10` | tee -a log'
142
    # FIXME: #9597
143
    # run/start is flaking for remote so let's wait for the container condition
144
    # to stop wasting energy until the root cause gets fixed.
145
    run_podman container wait --condition=exited --condition=stopped logtest
146
    run_podman ${events_backend} start -a logtest
147
    logfile=$(mktemp -p ${PODMAN_TMPDIR} logfileXXXXXXXX)
148
    $PODMAN $_PODMAN_TEST_OPTS ${events_backend} logs -f logtest > $logfile
149
    expected=$(mktemp -p ${PODMAN_TMPDIR} expectedXXXXXXXX)
150
    seq 1 20  > $expected
151
    diff -u ${expected} ${logfile}
152
}
153

154
@test "podman logs restarted - k8s-file" {
155
    _log_test_restarted k8s-file
156
}
157

158
@test "podman logs restarted journald" {
159
    # We can't use journald on RHEL as rootless: rhbz#1895105
160
    skip_if_journald_unavailable
161

162
    _log_test_restarted journald
163
}
164

165
@test "podman logs - journald log driver requires journald events backend" {
166
    skip_if_remote "remote does not support --events-backend"
167
    # We can't use journald on RHEL as rootless: rhbz#1895105
168
    skip_if_journald_unavailable
169

170
    run_podman --events-backend=file run --log-driver=journald -d --name test --replace $IMAGE ls /
171
    run_podman --events-backend=file logs test
172
    run_podman 125 --events-backend=file logs --follow test
173
    is "$output" "Error: using --follow with the journald --log-driver but without the journald --events-backend (file) is not supported" "journald logger requires journald eventer"
174
}
175

176
function _log_test_since() {
177
    local driver=$1
178

179
    s_before="before_$(random_string)_${driver}"
180
    s_after="after_$(random_string)_${driver}"
181

182
    before=$(date --iso-8601=seconds)
183
    run_podman run --log-driver=$driver -d --name test $IMAGE sh -c \
184
        "echo $s_before; trap 'echo $s_after; exit' SIGTERM; while :; do sleep 0.1; done"
185
    wait_for_output "$s_before" test
186

187
    # sleep a second to make sure the date is after the first echo
188
    # (We could instead use iso-8601=ns but seconds feels more real-world)
189
    sleep 1
190
    after=$(date --iso-8601=seconds)
191
    run_podman stop test
192

193
    run_podman logs test
194
    is "$output" \
195
        "$s_before
196
$s_after"
197

198
    run_podman logs --since $before test
199
    is "$output" \
200
        "$s_before
201
$s_after"
202

203
    run_podman logs --since $after test
204
    is "$output" "$s_after"
205
    run_podman rm -t 1 -f test
206
}
207

208
@test "podman logs - since k8s-file" {
209
    _log_test_since k8s-file
210
}
211

212
@test "podman logs - since journald" {
213
    # We can't use journald on RHEL as rootless: rhbz#1895105
214
    skip_if_journald_unavailable
215

216
    _log_test_since journald
217
}
218

219
function _log_test_until() {
220
    local driver=$1
221

222
    s_before="before_$(random_string)_${driver}"
223
    s_after="after_$(random_string)_${driver}"
224

225
    before=$(date --iso-8601=seconds)
226
    sleep 1
227
    run_podman run --log-driver=$driver -d --name test $IMAGE sh -c \
228
        "echo $s_before; trap 'echo $s_after; exit' SIGTERM; while :; do sleep 0.1; done"
229

230
    # sleep a second to make sure the date is after the first echo
231
    sleep 1
232
    run_podman stop test
233
    run_podman wait test
234

235
    # Sigh. Stupid journald has a lag. Wait a few seconds for it to catch up.
236
    retries=20
237
    s_both="$s_before
238
$s_after"
239
    while [[ $retries -gt 0 ]]; do
240
        run_podman logs test
241
        if [[ "$output" = "$s_both" ]]; then
242
            break
243
        fi
244
        retries=$((retries - 1))
245
        sleep 0.1
246
    done
247
    assert $retries -gt 0 \
248
           "Timed out waiting for before&after in podman logs: $output"
249

250
    run_podman logs --until $before test
251
    is "$output" "" "podman logs --until before"
252

253
    after=$(date --date='+1 second' --iso-8601=ns)
254

255
    run_podman logs --until $after test
256
    is "$output" "$s_both" "podman logs --until after"
257
    run_podman rm -t 0 -f test
258
}
259

260
@test "podman logs - until k8s-file" {
261
    _log_test_until k8s-file
262
}
263

264
@test "podman logs - until journald" {
265
    # We can't use journald on RHEL as rootless: rhbz#1895105
266
    skip_if_journald_unavailable
267

268
    _log_test_until journald
269
}
270

271
function _log_test_follow() {
272
    local driver=$1
273
    cname=$(random_string)
274
    contentA=$(random_string)
275
    contentB=$(random_string)
276
    contentC=$(random_string)
277
    local events_backend=$(_additional_events_backend $driver)
278

279
    if [[ -n "${events_backend}" ]]; then
280
        skip_if_remote "remote does not support --events-backend"
281
    fi
282

283
    # Note: it seems we need at least three log lines to hit #11461.
284
    run_podman ${events_backend} run --log-driver=$driver --name $cname $IMAGE sh -c "echo $contentA; echo $contentB; echo $contentC"
285
    run_podman ${events_backend} logs -f $cname
286
    is "$output" "$contentA
287
$contentB
288
$contentC" "logs -f on exited container works"
289

290
    run_podman ${events_backend} rm -t 0 -f $cname
291
}
292

293
@test "podman logs - --follow k8s-file" {
294
    _log_test_follow k8s-file
295
}
296

297
@test "podman logs - --follow journald" {
298
    # We can't use journald on RHEL as rootless: rhbz#1895105
299
    skip_if_journald_unavailable
300

301
    _log_test_follow journald
302
}
303

304
function _log_test_follow_since() {
305
    local driver=$1
306
    cname=$(random_string)
307
    content=$(random_string)
308
    local events_backend=$(_additional_events_backend $driver)
309

310
    if [[ -n "${events_backend}" ]]; then
311
        skip_if_remote "remote does not support --events-backend"
312
    fi
313

314
    run_podman ${events_backend} run --log-driver=$driver --name $cname $IMAGE echo "$content"
315
    # Using --since 0s can flake because the log might written in the second as the logs call is made.
316
    # The -1s makes sure we only read logs that would be created 1s in the future which cannot happen.
317
    run_podman ${events_backend} logs --since -1s -f $cname
318
    assert "$output" == "" "logs --since -f on exited container works"
319

320
    run_podman ${events_backend} rm -t 0 -f $cname
321

322
    # Now do the same with a running container to check #16950.
323
    run_podman ${events_backend} run --log-driver=$driver --name $cname -d $IMAGE \
324
        sh -c "sleep 1; while :; do echo $content && sleep 5; done"
325

326
    # sleep is required to make sure the podman event backend no longer sees the start event in the log
327
    # This value must be greater or equal than the value given in --since below
328
    sleep 0.2
329

330
    # Make sure podman logs actually follows by giving a low timeout and check that the command times out
331
    PODMAN_TIMEOUT=3 run_podman 124 ${events_backend} logs --since 0.1s -f $cname
332
    assert "$output" =~ "^$content
333
timeout: sending signal TERM to command.*" "logs --since -f on running container works"
334

335
    run_podman ${events_backend} rm -t 0 -f $cname
336
}
337

338
@test "podman logs - --since --follow k8s-file" {
339
    _log_test_follow_since k8s-file
340
}
341

342
# bats test_tags=distro-integration
343
@test "podman logs - --since --follow journald" {
344
    # We can't use journald on RHEL as rootless: rhbz#1895105
345
    skip_if_journald_unavailable
346

347
    _log_test_follow_since journald
348
}
349

350
function _log_test_follow_until() {
351
    local driver=$1
352
    cname=$(random_string)
353
    content=$(random_string)
354
    local events_backend=$(_additional_events_backend $driver)
355

356
    if [[ -n "${events_backend}" ]]; then
357
        skip_if_remote "remote does not support --events-backend"
358
    fi
359

360
    run_podman ${events_backend} run --log-driver=$driver --name $cname -d $IMAGE \
361
        sh -c "n=1;while :; do echo $content--\$n; n=\$((n+1));sleep 0.1; done"
362

363
    t0=$SECONDS
364
    # The logs command should exit after the until time even when follow is set
365
    PODMAN_TIMEOUT=10 run_podman ${events_backend} logs --until 3s -f $cname
366
    t1=$SECONDS
367
    logs_seen="$output"
368

369
    # The delta should be 3 but because it could be a bit longer on a slow system such as CI we also accept 4.
370
    delta_t=$(( $t1 - $t0 ))
371
    assert $delta_t -gt 2 "podman logs --until: exited too early!"
372
    assert $delta_t -lt 5 "podman logs --until: exited too late!"
373

374
    # Impossible to know how many lines we'll see, but require at least two
375
    assert "$logs_seen" =~ "$content--1
376
$content--2.*" "logs --until -f on running container works"
377

378
    run_podman ${events_backend} rm -t 0 -f $cname
379
}
380

381
@test "podman logs - --until --follow k8s-file" {
382
    _log_test_follow_until k8s-file
383
}
384

385
# bats test_tags=distro-integration
386
@test "podman logs - --until --follow journald" {
387
    # We can't use journald on RHEL as rootless: rhbz#1895105
388
    skip_if_journald_unavailable
389

390
    _log_test_follow_until journald
391
}
392

393
# https://github.com/containers/podman/issues/19545
394
@test "podman logs --tail, k8s-file with partial lines" {
395
    cname="tail_container"
396

397
    # "-t" gives us ^Ms (CRs) in the log
398
    run_podman run --name $cname --log-driver k8s-file -t $IMAGE echo hi
399

400
    # Hand-craft a log file with partial lines and carriage returns
401
    run_podman inspect --format '{{.HostConfig.LogConfig.Path}}' $cname
402
    logpath="$output"
403
    timestamp=$(head -n1 "$logpath" | awk '{print $1}')
404
    cr=$'\r'
405
    nl=$'\n'
406
    # Delete, don't overwrite, in case conmon still has the fd open
407
    rm -f $logpath
408
    cat > $logpath <<EOF
409
$timestamp stdout F podman1$cr
410
$timestamp stdout P podman2
411
$timestamp stdout F $cr
412
$timestamp stdout F podman3$cr
413
EOF
414

415
    # FIXME: remove after 2024-01-01 if no more flakes seen.
416
    cat -vET $logpath
417

418
    expect1="podman3${cr}"
419
    expect2="podman2${cr}${nl}podman3${cr}"
420
    expect3="podman1${cr}${nl}podman2${cr}${nl}podman3${cr}"
421

422
    # This always worked
423
    run_podman logs --tail 1 $cname
424
    assert "$output" = "$expect1" "--tail 1"
425

426
    # Prior to this PR, the first line would be "^M" without the podman
427
    run_podman logs --tail 2 $cname
428
    assert "$output" = "$expect2" "--tail 2"
429

430
    # Confirm that we won't overrun
431
    for i in 3 4 5; do
432
        run_podman logs --tail $i $cname
433
        assert "$output" = "$expect3" "--tail $i"
434
    done
435

436
    run_podman rm $cname
437
}
438

439
# vim: filetype=sh
440