Project

General

Profile

Actions
Copy link

Bug #5198

closed

eve/stats: ASAN error when eve output file can't be opened.

Added by Victor Julien over 3 years ago. Updated 11 months ago.

Status:
Closed
Priority:
Normal
Assignee:
Jeff Lucovsky
Target version:
7.0.0-rc1
Affected Versions:
Effort:
Difficulty:
Label:

Description

  - eve-log:
      enabled: yes
      filetype: regular #regular|syslog|unix_dgram|unix_stream|redis
      filename: /ev/null
      # Enable for multi-threaded eve.json output; output files are amended with
      # with an identifier, e.g., eve.9.json
      threaded: true

Commandline:
./src/suricata -c suricata.yaml -l tmp --disable-detection -r ~/pcap --runmode=single

Leads to:

$ ./src/suricata -c suricata.yaml -l tmp --disable-detection -r /pcap --runmode=single
[4153800] 20/3/2022 -- 15:24:26 - (suricata.c:1143) <Notice> (LogVersion) -- This is Suricata version 7.0.0-dev (308b3deb8 2022-03-20) running in USER mode
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153802] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153804] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153806] 20/3/2022 -- 15:24:26 - (util-logopenfile.c:401) <Error> (SCLogOpenFileFp) -- [ERRCODE: SC_ERR_FOPEN(44)] - Error opening file: "/dev/null.1": Permission denied
[4153800] 20/3/2022 -- 15:24:26 - (tm-threads.c:2040) <Notice> (TmThreadWaitOnThreadInit) -- Threads created -> W: 1 FM: 1 FR: 1   Engine started.
^C[4153800] 20/3/2022 -- 15:24:32 - (suricata.c:2806) <Notice> (SuricataMainLoop) -- Signal Received.  Stopping engine.
=================================================================
==4153800==ERROR: AddressSanitizer: heap-buffer-overflow on address 0x602000036040 at pc 0x000000916c1e bp 0x7fc74e6186b0 sp 0x7fc74e6186a8
READ of size 8 at 0x602000036040 thread T5 (CS)
    #0 0x916c1d in OutputJSONMemBufferCallback (/home/victor/dev/suricata/src/suricata+0x916c1d)
    #1 0x7fc754c68ca0  (/lib/x86_64-linux-gnu/libjansson.so.4+0x2ca0)
    #2 0x7fc754c68fbb in json_dump_callback (/lib/x86_64-linux-gnu/libjansson.so.4+0x2fbb)
    #3 0x917bd6 in OutputJSONBuffer (/home/victor/dev/suricata/src/suricata+0x917bd6)
    #4 0x960af8 in JsonStatsLogger (/home/victor/dev/suricata/src/suricata+0x960af8)
    #5 0x96732a in OutputStatsLog (/home/victor/dev/suricata/src/suricata+0x96732a)
    #6 0x6dd5b6 in StatsOutput (/home/victor/dev/suricata/src/suricata+0x6dd5b6)
    #7 0x6d9969 in StatsMgmtThread (/home/victor/dev/suricata/src/suricata+0x6d9969)
    #8 0x7fc754c4b608 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x8608)
    #9 0x7fc754a3a162 in clone (/lib/x86_64-linux-gnu/libc.so.6+0x11f162)

0x602000036040 is located 0 bytes to the right of 16-byte region [0x602000036030,0x602000036040)
allocated by thread T5 (CS) here:
    #0 0x58f21d in malloc (/home/victor/dev/suricata/src/suricata+0x58f21d)
    #1 0x615aa4 in SCMallocFunc (/home/victor/dev/suricata/src/suricata+0x615aa4)
    #2 0xbcefbd in LogStatsLogThreadInit (/home/victor/dev/suricata/src/suricata+0xbcefbd)
    #3 0x96780b in OutputStatsLogThreadInit (/home/victor/dev/suricata/src/suricata+0x96780b)
    #4 0x6d9650 in StatsMgmtThread (/home/victor/dev/suricata/src/suricata+0x6d9650)
    #5 0x7fc754c4b608 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x8608)

Thread T5 (CS) created by T0 (Suricata-Main) here:
    #0 0x57957c in pthread_create (/home/victor/dev/suricata/src/suricata+0x57957c)
    #1 0x5ddd94 in TmThreadSpawn (/home/victor/dev/suricata/src/suricata+0x5ddd94)
    #2 0x6d8730 in StatsSpawnThreads (/home/victor/dev/suricata/src/suricata+0x6d8730)
    #3 0x979b4b in RunModeDispatch (/home/victor/dev/suricata/src/suricata+0x979b4b)
    #4 0x5c3fb5 in SuricataMain (/home/victor/dev/suricata/src/suricata+0x5c3fb5)
    #5 0x5c0281 in main (/home/victor/dev/suricata/src/suricata+0x5c0281)
    #6 0x7fc75493f0b2 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x240b2)

SUMMARY: AddressSanitizer: heap-buffer-overflow (/home/victor/dev/suricata/src/suricata+0x916c1d) in OutputJSONMemBufferCallback
Shadow bytes around the buggy address:
  0x0c047fffebb0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c047fffebc0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c047fffebd0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c047fffebe0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c047fffebf0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
=>0x0c047fffec00: fa fa 00 fa fa fa 00 00[fa]fa 00 00 fa fa 00 00
  0x0c047fffec10: fa fa 00 00 fa fa 00 00 fa fa 00 00 fa fa 00 00
  0x0c047fffec20: fa fa 00 00 fa fa 00 00 fa fa 00 00 fa fa 00 00
  0x0c047fffec30: fa fa 06 fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c047fffec40: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c047fffec50: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
Shadow byte legend (one shadow byte represents 8 application bytes):
  Addressable:           00
  Partially addressable: 01 02 03 04 05 06 07 
  Heap left redzone:       fa
  Freed heap region:       fd
  Stack left redzone:      f1
  Stack mid redzone:       f2
  Stack right redzone:     f3
  Stack after return:      f5
  Stack use after scope:   f8
  Global redzone:          f9
  Global init order:       f6
  Poisoned by user:        f7
  Container overflow:      fc
  Array cookie:            ac
  Intra object redzone:    bb
  ASan internal:           fe
  Left alloca redzone:     ca
  Right alloca redzone:    cb
  Shadow gap:              cc
==4153800==ABORTING

threaded: false works as expected.

Related issues 2 (0 open — 2 closed)

Related to Suricata - Bug #5836: output: abort triggered on no permission testClosedJeff LucovskyActions
Related to Suricata - Bug #7447: NULL dereference in ThreadLogFileHashFreeFunc in bug-5198 SV testClosedJeff LucovskyActions
Actions
Copy link
 #1

Updated by Jeff Lucovsky over 3 years ago

  • Status changed from Assigned to In Progress
Actions
Copy link
 #2

Updated by Jeff Lucovsky over 3 years ago

  • Status changed from In Progress to In Review
Actions
Copy link
 #4

Updated by Victor Julien about 3 years ago

  • Target version changed from 7.0.0-beta1 to 7.0.0-rc1
Actions
Copy link
 #5

Updated by Jeff Lucovsky almost 3 years ago

  • Subject changed from eve/stats: ASAN error to eve/stats: ASAN error when eve output file can't be opened.
  • Description updated (diff)
Actions
Copy link
 #6

Updated by Jeff Lucovsky almost 3 years ago

  • Status changed from In Review to Closed
Actions
Copy link
 #7

Updated by Jeff Lucovsky over 2 years ago

  • Related to Bug #5836: output: abort triggered on no permission test added
Actions
Copy link
 #8

Updated by Philippe Antoine 11 months ago

Is this really fixed ?

I get

bug-5198 catena$ more output/stderr 
Error: logopenfile: Error opening file: "/Users/catena/catena/prod/suricata-verify/tests/bug-5198/output/noperms/eve.1.json": Permission denied [SCLogOpenFileFp:util-logopenfile.c:425]
Error: logopenfile: Unable to open slot 1 for file /Users/catena/catena/prod/suricata-verify/tests/bug-5198/output/noperms/eve.json [LogFileEnsureExists:util-logopenfile.c:732]
AddressSanitizer:DEADLYSIGNAL
=================================================================
==3267==ERROR: AddressSanitizer: SEGV on unknown address 0x000000000078 (pc 0x0001026abc0d bp 0x7ff7bdc8d630 sp 0x7ff7bdc8d610 T0)
==3267==The signal is caused by a READ memory access.
==3267==Hint: address points to the zero page.
    #0 0x1026abc0d in ThreadLogFileHashFreeFunc util-logopenfile.c:352
    #1 0x1026a052b in HashTableRemove util-hash.c:152
    #2 0x1026aec12 in LogFileEnsureExists util-logopenfile.c:733
    #3 0x1025beea4 in OutputStatsLogInitSub output-json-stats.c:486
    #4 0x1025df085 in RunModeInitializeOutputs runmodes.c:827
    #5 0x102662d93 in SuricataInit suricata.c:2956
    #6 0x102272190 in main main.c:54
    #7 0x7ff809db4344 in start+0x774 (dyld:x86_64+0xfffffffffff5c344)

Actions
Copy link
 #9

Updated by Philippe Antoine 11 months ago

  • Related to Bug #7447: NULL dereference in ThreadLogFileHashFreeFunc in bug-5198 SV test added
Actions
Copy link

Also available in: Atom PDF